diff --git a/services/inc/config.h b/services/inc/config.h index 0ec0df45f8..30bade743f 100644 --- a/services/inc/config.h +++ b/services/inc/config.h @@ -28,9 +28,13 @@ #undef DEBUG_BUILD #endif -#if defined(DEBUG_BUILD) && !defined(LOG_INCLUDE_SOURCE_INFO) -#define LOG_INCLUDE_SOURCE_INFO +#ifndef LOG_INCLUDE_SOURCE_INFO +#ifdef DEBUG_BUILD +#define LOG_INCLUDE_SOURCE_INFO 1 +#else +#define LOG_INCLUDE_SOURCE_INFO 0 #endif +#endif // !defined(LOG_INCLUDE_SOURCE_INFO) #define MAX_SEC_WAIT_CONNECT 8 // Number of second a TCP, spark will wait #define MAX_FAILED_CONNECTS 2 // Number of time a connect can fail diff --git a/services/inc/logging.h b/services/inc/logging.h index f6228dd9f9..a4012284cd 100644 --- a/services/inc/logging.h +++ b/services/inc/logging.h @@ -106,8 +106,8 @@ Following macros configure logging module at compile time: LOG_INCLUDE_SOURCE_INFO - allows to include source info (file name, function name, line number) - into messages generated by the logging macros. By default, this macro is defined only for debug - builds (see config.h). + into messages generated by the logging macros. Default value is 0 for release builds and 1 for + debug builds (see config.h). LOG_COMPILE_TIME_LEVEL - allows to strip any logging output that is below of certain logging level at compile time. Default value is LOG_LEVEL_ALL meaning that no compile-time filtering is applied. @@ -236,6 +236,10 @@ extern void HAL_Delay_Microseconds(uint32_t delay); #define LOG_MAX_STRING_LENGTH 160 #endif +#ifndef LOG_INCLUDE_SOURCE_INFO +#define LOG_INCLUDE_SOURCE_INFO 0 +#endif + // Sets log message attribute #define LOG_ATTR_SET(_attr, _name, _val) \ do { \ @@ -308,7 +312,7 @@ static const char* const _log_category = NULL; #endif // !defined(__cplusplus) -#ifdef LOG_INCLUDE_SOURCE_INFO +#if LOG_INCLUDE_SOURCE_INFO #define _LOG_ATTR_SET_SOURCE_INFO(_attr) \ LOG_ATTR_SET(_attr, file, __FILE__); \ LOG_ATTR_SET(_attr, line, __LINE__); \ diff --git a/services/src/logging.cpp b/services/src/logging.cpp index 6612302d2e..47c19441c3 100644 --- a/services/src/logging.cpp +++ b/services/src/logging.cpp @@ -78,7 +78,8 @@ void log_set_callbacks(log_message_callback_type log_msg, log_write_callback_typ } void log_message_v(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, va_list args) { - if (!log_msg_callback && (!log_compat_callback || level < log_compat_level)) { + const log_message_callback_type msg_callback = log_msg_callback; + if (!msg_callback && (!log_compat_callback || level < log_compat_level)) { return; } // Set default attributes @@ -86,12 +87,12 @@ void log_message_v(int level, const char *category, LogAttributes *attr, void *r LOG_ATTR_SET(*attr, time, HAL_Timer_Get_Milli_Seconds()); } char buf[LOG_MAX_STRING_LENGTH]; - if (log_msg_callback) { + if (msg_callback) { const int n = vsnprintf(buf, sizeof(buf), fmt, args); if (n > (int)sizeof(buf) - 1) { buf[sizeof(buf) - 2] = '~'; } - log_msg_callback(buf, level, category, attr, 0); + msg_callback(buf, level, category, attr, 0); } else { // Using compatibility callback const char* const levelName = log_level_name(level, 0); @@ -127,8 +128,9 @@ void log_write(int level, const char *category, const char *data, size_t size, v if (!size) { return; } - if (log_write_callback) { - log_write_callback(data, size, level, category, 0); + const log_write_callback_type write_callback = log_write_callback; + if (write_callback) { + write_callback(data, size, level, category, 0); } else if (log_compat_callback && level >= log_compat_level) { // Compatibility callback expects null-terminated strings if (!data[size - 1]) { @@ -148,7 +150,8 @@ void log_write(int level, const char *category, const char *data, size_t size, v } void log_printf_v(int level, const char *category, void *reserved, const char *fmt, va_list args) { - if (!log_write_callback && (!log_compat_callback || level < log_compat_level)) { + const log_write_callback_type write_callback = log_write_callback; + if (!write_callback && (!log_compat_callback || level < log_compat_level)) { return; } char buf[LOG_MAX_STRING_LENGTH]; @@ -157,8 +160,8 @@ void log_printf_v(int level, const char *category, void *reserved, const char *f buf[sizeof(buf) - 2] = '~'; n = sizeof(buf) - 1; } - if (log_write_callback) { - log_write_callback(buf, n, level, category, 0); + if (write_callback) { + write_callback(buf, n, level, category, 0); } else { log_compat_callback(buf); // Compatibility callback } @@ -172,7 +175,8 @@ void log_printf(int level, const char *category, void *reserved, const char *fmt } void log_dump(int level, const char *category, const void *data, size_t size, int flags, void *reserved) { - if (!size || (!log_write_callback && (!log_compat_callback || level < log_compat_level))) { + const log_write_callback_type write_callback = log_write_callback; + if (!size || (!write_callback && (!log_compat_callback || level < log_compat_level))) { return; } static const char hex[] = "0123456789abcdef"; @@ -184,8 +188,8 @@ void log_dump(int level, const char *category, const void *data, size_t size, in buf[offs++] = hex[b >> 4]; buf[offs++] = hex[b & 0x0f]; if (offs == sizeof(buf) - 1) { - if (log_write_callback) { - log_write_callback(buf, sizeof(buf) - 1, level, category, 0); + if (write_callback) { + write_callback(buf, sizeof(buf) - 1, level, category, 0); } else { log_compat_callback(buf); } @@ -193,8 +197,8 @@ void log_dump(int level, const char *category, const void *data, size_t size, in } } if (offs) { - if (log_write_callback) { - log_write_callback(buf, offs, level, category, 0); + if (write_callback) { + write_callback(buf, offs, level, category, 0); } else { buf[offs] = 0; log_compat_callback(buf); @@ -203,8 +207,9 @@ void log_dump(int level, const char *category, const void *data, size_t size, in } int log_enabled(int level, const char *category, void *reserved) { - if (log_enabled_callback) { - return log_enabled_callback(level, category, 0); + const log_enabled_callback_type enabled_callback = log_enabled_callback; + if (enabled_callback) { + return enabled_callback(level, category, 0); } if (log_compat_callback && level >= log_compat_level) { // Compatibility callback return 1; diff --git a/system-dynalib/makefile b/system-dynalib/makefile index 542f0ec0a4..da49e7ca9f 100644 --- a/system-dynalib/makefile +++ b/system-dynalib/makefile @@ -4,6 +4,6 @@ SYSTEM_DYNALIB_MODULE_PATH=. TARGET_TYPE = a BUILD_PATH_EXT = $(SYSTEM_DYNALIB_BUILD_PATH_EXT) -DEPENDENCIES = system dynalib +DEPENDENCIES = system dynalib hal include ../build/arm-tlm.mk diff --git a/system/inc/active_object.h b/system/inc/active_object.h index 9410ca04df..8e9cf1e3dc 100644 --- a/system/inc/active_object.h +++ b/system/inc/active_object.h @@ -19,12 +19,15 @@ #pragma once +#include + #if PLATFORM_THREADING #include #include #include #include + #include "channel.h" #include "concurrent_hal.h" @@ -435,4 +438,31 @@ class ActiveObjectThreadQueue : public ActiveObjectQueue -#endif +#endif // PLATFORM_THREADING + +/** + * This class implements a queue of asynchronous calls that can be scheduled from an ISR and then + * invoked from an event loop running in a regular thread. + */ +class ISRTaskQueue { +public: + typedef void(*TaskFunc)(void*); + + explicit ISRTaskQueue(size_t size); + ~ISRTaskQueue(); + + bool enqueue(TaskFunc func, void* data = nullptr); // Called from an ISR + bool process(); // Called from the primary thread + +private: + struct Task { + TaskFunc func; + void* data; + Task* next; + }; + + Task* tasks_; + Task* availTask_; // Task pool + Task* firstTask_; // Task queue + Task* lastTask_; +}; diff --git a/system/inc/system_control.h b/system/inc/system_control.h index ab55244a6b..48a506bba2 100644 --- a/system/inc/system_control.h +++ b/system/inc/system_control.h @@ -26,20 +26,99 @@ #ifndef SYSTEM_CONTROL_H_ #define SYSTEM_CONTROL_H_ +#include + #include "usb_hal.h" +typedef enum DataFormat { // TODO: Move to appropriate header + DATA_FORMAT_INVALID = 0, + DATA_FORMAT_BINARY = 10, // Generic binary format + DATA_FORMAT_TEXT = 20, // Generic text format + DATA_FORMAT_JSON = 30 +} DataFormat; + #ifdef USB_VENDOR_REQUEST_ENABLE +// Maximum supported size of USB request/reply data +#define USB_REQUEST_BUFFER_SIZE 512 + +#ifdef __cplusplus +extern "C" { +#endif + +typedef enum USBRequestType { + USB_REQUEST_INVALID = 0, + USB_REQUEST_CUSTOM = 10, // Customizable request processed in application thread + USB_REQUEST_DEVICE_ID = 20, + USB_REQUEST_SYSTEM_VERSION = 30, + USB_REQUEST_RESET = 40, + USB_REQUEST_DFU_MODE = 50, + USB_REQUEST_SAFE_MODE = 60, + USB_REQUEST_LISTENING_MODE = 70, + USB_REQUEST_LOG_CONFIG = 80 +} USBRequestType; + +typedef enum USBRequestResult { + USB_REQUEST_RESULT_OK = 0, + USB_REQUEST_RESULT_ERROR = 10 +} USBRequestResult; + +typedef struct USBRequest { + size_t size; // Structure size + int type; // Request type (as defined by USBRequestType enum) + char* data; // Data buffer + size_t request_size; // Request size + size_t reply_size; // Reply size (initialized to 0) + int format; // Data format (as defined by DataFormat enum) +} USBRequest; + +// Callback invoked for USB requests that should be processed at application side +typedef bool(*usb_request_app_handler_type)(USBRequest* req, void* reserved); + +// Sets application callback for USB requests +void system_set_usb_request_app_handler(usb_request_app_handler_type handler, void* reserved); + +// Signals that processing of the USB request has finished +void system_set_usb_request_result(USBRequest* req, int result, void* reserved); + +#ifdef __cplusplus +} // extern "C" + class SystemControlInterface { public: SystemControlInterface(); ~SystemControlInterface(); - uint8_t handleVendorRequest(HAL_USB_SetupRequest* req); + + static void setRequestResult(USBRequest* req, USBRequestResult result); private: - static uint8_t vendorRequestCallback(HAL_USB_SetupRequest* req, void* ptr); + struct USBRequestData { + USBRequest req; // Externally accessible part of the request data + USBRequestResult result; + bool active; + volatile bool ready; + + USBRequestData(); + ~USBRequestData(); + }; + + USBRequestData usbReq_; + + uint8_t handleVendorRequest(HAL_USB_SetupRequest* req); + + uint8_t enqueueRequest(HAL_USB_SetupRequest* req, DataFormat fmt = DATA_FORMAT_BINARY); + uint8_t fetchRequestResult(HAL_USB_SetupRequest* req); + + static void processSystemRequest(void* data); // Called by SystemThread + static void processAppRequest(void* data); // Called by ApplicationThread + + static uint8_t vendorRequestCallback(HAL_USB_SetupRequest* req, void* data); // Called by HAL + + static bool setRequestResult(USBRequest* req, const char* data, size_t size); }; +#endif // __cplusplus + #endif // USB_VENDOR_REQUEST_ENABLE -#endif // SYSTEM_CONTROL_H_ \ No newline at end of file +#endif // SYSTEM_CONTROL_H_ diff --git a/system/inc/system_dynalib.h b/system/inc/system_dynalib.h index a4512a0d4f..841c8f43eb 100644 --- a/system/inc/system_dynalib.h +++ b/system/inc/system_dynalib.h @@ -25,6 +25,7 @@ #define SYSTEM_DYNALIB_H #include "dynalib.h" +#include "usb_hal.h" #ifdef DYNALIB_EXPORT #include "system_mode.h" @@ -33,6 +34,7 @@ #include "system_update.h" #include "system_event.h" #include "system_version.h" +#include "system_control.h" #endif DYNALIB_BEGIN(system) @@ -62,8 +64,16 @@ DYNALIB_FN(18, system, Spark_Finish_Firmware_Update, int(FileTransfer::Descripto DYNALIB_FN(19, system, application_thread_current, uint8_t(void*)) DYNALIB_FN(20, system, system_thread_current, uint8_t(void*)) +#ifdef USB_VENDOR_REQUEST_ENABLE +DYNALIB_FN(21, system, system_set_usb_request_app_handler, void(usb_request_app_handler_type, void*)) +DYNALIB_FN(22, system, system_set_usb_request_result, void(USBRequest*, int, void*)) +#define BASE_IDX 23 +#else +#define BASE_IDX 21 +#endif // USB_VENDOR_REQUEST_ENABLE + DYNALIB_END(system) +#undef BASE_IDX #endif /* SYSTEM_DYNALIB_H */ - diff --git a/system/inc/system_task.h b/system/inc/system_task.h index 664245561d..c6ac028e8c 100644 --- a/system/inc/system_task.h +++ b/system/inc/system_task.h @@ -30,6 +30,9 @@ #include "socket_hal.h" #include "system_cloud.h" #include "wlan_hal.h" +#include "active_object.h" + +extern ISRTaskQueue SystemISRTaskQueue; #ifdef __cplusplus extern "C" { diff --git a/system/src/active_object.cpp b/system/src/active_object.cpp index f6d8aa280f..3622faf30f 100644 --- a/system/src/active_object.cpp +++ b/system/src/active_object.cpp @@ -17,10 +17,13 @@ ****************************************************************************** */ +#include "active_object.h" + +#include "spark_wiring_interrupts.h" + #if PLATFORM_THREADING #include -#include "active_object.h" #include "concurrent_hal.h" #include "timer_hal.h" @@ -74,4 +77,79 @@ void ActiveObjectBase::run_active_object(ActiveObjectBase* object) object->run(); } -#endif +#endif // PLATFORM_THREADING + +ISRTaskQueue::ISRTaskQueue(size_t size) : + tasks_(nullptr), + availTask_(nullptr), + firstTask_(nullptr), + lastTask_(nullptr) { + if (size) { + // Initialize pool of task objects + tasks_ = new(std::nothrow) Task[size]; + if (tasks_) { + for (size_t i = 0; i < size; ++i) { + Task* t = tasks_ + i; + if (i != size - 1) { + t->next = t + 1; + } else { + t->next = nullptr; + } + } + } + availTask_ = tasks_; + } +} + +ISRTaskQueue::~ISRTaskQueue() { + delete[] tasks_; +} + +bool ISRTaskQueue::enqueue(TaskFunc func, void* data) { + SPARK_ASSERT(func && HAL_IsISR()); + ATOMIC_BLOCK() { // Prevent preemption of the current ISR + // Take task object from the pool + Task* t = availTask_; + if (!t) { + return false; + } + availTask_ = t->next; + // Initialize task object + t->func = func; + t->data = data; + t->next = nullptr; + // Add task object to the queue + if (lastTask_) { + lastTask_->next = t; + } else { // The queue is empty + firstTask_ = t; + } + lastTask_ = t; + } + return true; +} + +bool ISRTaskQueue::process() { + SPARK_ASSERT(!HAL_IsISR()); + TaskFunc func = nullptr; + void* data = nullptr; + ATOMIC_BLOCK() { + // Take task object from the queue + Task *t = firstTask_; + if (!t) { + return false; + } + firstTask_ = firstTask_->next; + if (!firstTask_) { + lastTask_ = nullptr; + } + func = t->func; + data = t->data; + // Return task object to the pool + t->next = availTask_; + availTask_ = t; + } + // Invoke task function + func(data); + return true; +} diff --git a/system/src/main.cpp b/system/src/main.cpp index eb83885b1d..6f0034df1c 100644 --- a/system/src/main.cpp +++ b/system/src/main.cpp @@ -482,8 +482,6 @@ void manage_safe_mode() system_get_flag(SYSTEM_FLAG_STARTUP_SAFE_LISTEN_MODE, &value, nullptr); if (value) { - // disable logging so that it doesn't interfere with serial output - set_logger_output(nullptr, NO_LOG_LEVEL); system_set_flag(SYSTEM_FLAG_STARTUP_SAFE_LISTEN_MODE, 0, 0); // flag listening mode network_listen(0, 0, 0); diff --git a/system/src/system_control.cpp b/system/src/system_control.cpp index a508e667fa..00498fcb9d 100644 --- a/system/src/system_control.cpp +++ b/system/src/system_control.cpp @@ -24,44 +24,64 @@ */ #include "system_control.h" + #include "deviceid_hal.h" -#include "spark_wiring.h" + +#include "system_task.h" +#include "system_threading.h" + +#include "spark_wiring_system.h" #ifdef USB_VENDOR_REQUEST_ENABLE -static SystemControlInterface controlInterface; +namespace { -enum ControlRequest { - REQUEST_GET_DEVICE_ID = 0x0000, - REQUEST_GET_SYSTEM_VERSION = 0x0001, - REQUEST_RESET = 0x0002, - // Perhaps could be combined into a signle request and a mode could be supplied in wValue? - REQUEST_ENTER_DFU_MODE = 0x0003, - REQUEST_ENTER_LISTENING_MODE = 0x0004 - // -}; +SystemControlInterface systemControl; -SystemControlInterface::SystemControlInterface() { - HAL_USB_Set_Vendor_Request_Callback(&SystemControlInterface::vendorRequestCallback, static_cast(this)); +usb_request_app_handler_type usbReqAppHandler = nullptr; + +} // namespace + +// :: +void system_set_usb_request_app_handler(usb_request_app_handler_type handler, void* reserved) { + usbReqAppHandler = handler; } -SystemControlInterface::~SystemControlInterface() { - HAL_USB_Set_Vendor_Request_Callback(nullptr, nullptr); +void system_set_usb_request_result(USBRequest* req, int result, void* reserved) { + SystemControlInterface::setRequestResult(req, (USBRequestResult)result); } -uint8_t SystemControlInterface::vendorRequestCallback(HAL_USB_SetupRequest* req, void* ptr) { - SystemControlInterface* self = static_cast(ptr); - if (self) - return self->handleVendorRequest(req); +// SystemControlInterface::USBRequestData +SystemControlInterface::USBRequestData::USBRequestData() : + result(USB_REQUEST_RESULT_ERROR), + active(false), + ready(false) { + req.size = sizeof(USBRequest); + req.type = USB_REQUEST_INVALID; + req.data = (char*)malloc(USB_REQUEST_BUFFER_SIZE); + req.request_size = 0; + req.reply_size = 0; + req.format = DATA_FORMAT_INVALID; +} - return 1; +SystemControlInterface::USBRequestData::~USBRequestData() { + free(req.data); +} + +// SystemControlInterface +SystemControlInterface::SystemControlInterface() { + HAL_USB_Set_Vendor_Request_Callback(vendorRequestCallback, static_cast(this)); +} + +SystemControlInterface::~SystemControlInterface() { + HAL_USB_Set_Vendor_Request_Callback(nullptr, nullptr); } uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { /* * This callback should process vendor-specific SETUP requests from the host. * NOTE: This callback is called from an ISR. - * + * * Each request contains the following fields: * - bmRequestType - request type bit mask. Since only vendor-specific device requests are forwarded * to this callback, the only bit that should be of intereset is @@ -77,12 +97,12 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { * Device -> Host requests request the device to send up to wLength bytes of data. * * This callback should return 0 if the request has been correctly handled or 1 otherwise. - * + * * When handling Device->Host requests with data stage, this callback should fill req->data buffer with * up to wLength bytes of data if req->data != NULL (which should be the case when wLength <= 64) * or set req->data to point to some buffer which contains up to wLength bytes of data. * wLength may be safely modified to notify that there is less data in the buffer than requested by the host. - * + * * [1] Host -> Device requests with data stage containing up to 64 bytes can be handled by * an internal buffer in HAL. For requests larger than 64 bytes, the vendor request callback * needs to provide a buffer of an appropriate size: @@ -95,26 +115,17 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { * req->data should contain wLength bytes received from the host. */ - /* + /* * We are handling only bRequest = 0x50 ('P') requests. - * The request type itself (enum ControlRequest) should be in wIndex field. + * The request type itself (enum USBRequestType) should be in wIndex field. */ if (req->bRequest != 0x50) return 1; if (req->bmRequestTypeDirection == 0) { // Host -> Device - - if (req->wLength && req->data == NULL) { - /* - * Currently not handled. - * See [1] - */ - return 1; - } - switch (req->wIndex) { - case REQUEST_RESET: { + case USB_REQUEST_RESET: { // FIXME: We probably shouldn't reset from an ISR. // The host will probably get an error that control request has timed out since we // didn't respond to it. @@ -122,7 +133,7 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { break; } - case REQUEST_ENTER_DFU_MODE: { + case USB_REQUEST_DFU_MODE: { // FIXME: We probably shouldn't enter DFU mode from an ISR. // The host will probably get an error that control request has timed out since we // didn't respond to it. @@ -130,7 +141,7 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { break; } - case REQUEST_ENTER_LISTENING_MODE: { + case USB_REQUEST_LISTENING_MODE: { // FIXME: We probably shouldn't enter listening mode from an ISR. // The host will probably get an error that control request has timed out since we // didn't respond to it. @@ -139,6 +150,14 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { break; } + case USB_REQUEST_LOG_CONFIG: { + return enqueueRequest(req, DATA_FORMAT_JSON); + } + + case USB_REQUEST_CUSTOM: { + return enqueueRequest(req); + } + default: { // Unknown request return 1; @@ -147,7 +166,7 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { } else { // Device -> Host switch (req->wIndex) { - case REQUEST_GET_DEVICE_ID: { + case USB_REQUEST_DEVICE_ID: { if (req->wLength == 0 || req->data == NULL) { // No data stage or requested > 64 bytes return 1; @@ -170,7 +189,7 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { break; } - case REQUEST_GET_SYSTEM_VERSION: { + case USB_REQUEST_SYSTEM_VERSION: { if (req->wLength == 0 || req->data == NULL) { // No data stage or requested > 64 bytes return 1; @@ -181,6 +200,11 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { break; } + case USB_REQUEST_LOG_CONFIG: + case USB_REQUEST_CUSTOM: { + return fetchRequestResult(req); + } + default: { // Unknown request return 1; @@ -191,4 +215,110 @@ uint8_t SystemControlInterface::handleVendorRequest(HAL_USB_SetupRequest* req) { return 0; } +uint8_t SystemControlInterface::enqueueRequest(HAL_USB_SetupRequest* req, DataFormat fmt) { + SPARK_ASSERT(req->bmRequestTypeDirection == 0); // Host to device + if (usbReq_.active && !usbReq_.ready) { + return 1; // // There is an active request already + } + if (req->wLength > 0) { + if (!usbReq_.req.data) { + return 1; // Initialization error + } + if (req->wLength > USB_REQUEST_BUFFER_SIZE) { + return 1; // Too large request + } + if (req->wLength <= 64) { + if (!req->data) { + return 1; // Invalid request info + } + memcpy(usbReq_.req.data, req->data, req->wLength); + } else if (!req->data) { + req->data = (uint8_t*)usbReq_.req.data; // Provide buffer for request data + return 0; // OK + } + } + // Schedule request for processing in the system thread's context + if (!SystemISRTaskQueue.enqueue(processSystemRequest, &usbReq_.req)) { + return 1; + } + usbReq_.req.type = (USBRequestType)req->wIndex; + usbReq_.req.request_size = req->wLength; + usbReq_.req.reply_size = 0; + usbReq_.req.format = fmt; + usbReq_.ready = false; + usbReq_.active = true; + return 0; +} + +uint8_t SystemControlInterface::fetchRequestResult(HAL_USB_SetupRequest* req) { + SPARK_ASSERT(req->bmRequestTypeDirection == 1); // Device to host + if (!usbReq_.ready) { + return 1; // No reply data available + } + if (usbReq_.req.type != (USBRequestType)req->wIndex) { + return 1; // Unexpected request type + } + if (usbReq_.result != USB_REQUEST_RESULT_OK) { + return 1; // Request has failed (TODO: Reply with a result code?) + } + if (req->wLength > 0) { + if (!usbReq_.req.data) { + return 1; // Initialization error + } + if (req->wLength < usbReq_.req.reply_size) { + return 1; // Too large reply + } + if (req->wLength <= 64) { + if (!req->data) { + return 1; // Invalid request info + } + memcpy(req->data, usbReq_.req.data, usbReq_.req.reply_size); + } else { + req->data = (uint8_t*)usbReq_.req.data; // Provide buffer with reply data + } + req->wLength = usbReq_.req.reply_size; + } + usbReq_.active = false; + // FIXME: Don't invalidate reply data for now (simplifies testing with usbtool) + // usbReq_.ready = false; + return 0; +} + +void SystemControlInterface::setRequestResult(USBRequest* req, USBRequestResult result) { + USBRequestData *r = (USBRequestData*)req; + r->result = result; + r->ready = true; +} + +void SystemControlInterface::processSystemRequest(void* data) { + USBRequest* req = static_cast(data); + switch (req->type) { + // Handle requests that should be processed by the system modules here + default: + if (usbReqAppHandler) { + processAppRequest(data); // Forward request to the application thread + } else { + setRequestResult(req, USB_REQUEST_RESULT_ERROR); + } + } +} + +void SystemControlInterface::processAppRequest(void* data) { + // FIXME: Request leak may occur if underlying asynchronous event cannot be queued + APPLICATION_THREAD_CONTEXT_ASYNC(processAppRequest(data)); + USBRequest* req = static_cast(data); + SPARK_ASSERT(usbReqAppHandler); // Checked in processSystemRequest() + if (!usbReqAppHandler(req, nullptr)) { + setRequestResult(req, USB_REQUEST_RESULT_ERROR); + } +} + +uint8_t SystemControlInterface::vendorRequestCallback(HAL_USB_SetupRequest* req, void* data) { + SystemControlInterface* self = static_cast(data); + if (self) { + return self->handleVendorRequest(req); + } + return 1; +} + #endif // USB_VENDOR_REQUEST_ENABLE diff --git a/system/src/system_task.cpp b/system/src/system_task.cpp index 4efacbf585..c91ae112ab 100644 --- a/system/src/system_task.cpp +++ b/system/src/system_task.cpp @@ -57,6 +57,7 @@ volatile uint8_t SPARK_LED_FADE = 1; volatile uint8_t Spark_Error_Count; volatile uint8_t SYSTEM_POWEROFF; +ISRTaskQueue SystemISRTaskQueue(4); void Network_Setup(bool threaded) { @@ -341,7 +342,12 @@ void manage_cloud_connection(bool force_events) handle_cloud_connection(force_events); } } -#endif +#endif // !SPARK_NO_CLOUD + +static void process_isr_task_queue() +{ + SystemISRTaskQueue.process(); +} #if Wiring_SetupButtonUX extern void system_handle_button_click(); @@ -354,6 +360,8 @@ void Spark_Idle_Events(bool force_events/*=false*/) ON_EVENT_DELTA(); spark_loop_total_millis = 0; + process_isr_task_queue(); + if (!SYSTEM_POWEROFF) { #if Wiring_SetupButtonUX diff --git a/user/build.mk b/user/build.mk index a2482d5109..e0ad8f8e72 100644 --- a/user/build.mk +++ b/user/build.mk @@ -82,5 +82,5 @@ CPPFLAGS += -D_POSIX_C_SOURCE=200809 endif # Use application source info regardless of release/debug build -CFLAGS += -DLOG_INCLUDE_SOURCE_INFO +CFLAGS += -DLOG_INCLUDE_SOURCE_INFO=1 LOG_MODULE_CATEGORY = app diff --git a/user/tests/accept/.gitignore b/user/tests/accept/.gitignore new file mode 100644 index 0000000000..4dbe29fb21 --- /dev/null +++ b/user/tests/accept/.gitignore @@ -0,0 +1 @@ +/.cache/ diff --git a/user/tests/accept/Gemfile b/user/tests/accept/Gemfile index 0e84b604e3..2838cc566d 100644 --- a/user/tests/accept/Gemfile +++ b/user/tests/accept/Gemfile @@ -1,3 +1,7 @@ source 'https://rubygems.org' gem 'aruba', '~> 0.14.1' +gem 'rspec-expectations', '~> 3.5.0' +gem 'concurrent-ruby', '~> 1.0.2' +gem 'em-rubyserial', '~> 0.0.2' gem 'diff_dirs', '~> 0.1.2' +gem 'hex_string', '~> 1.0.1' diff --git a/user/tests/accept/Gemfile.lock b/user/tests/accept/Gemfile.lock deleted file mode 100644 index 42aedaf6e2..0000000000 --- a/user/tests/accept/Gemfile.lock +++ /dev/null @@ -1,46 +0,0 @@ -GEM - remote: https://rubygems.org/ - specs: - aruba (0.14.1) - childprocess (~> 0.5.6) - contracts (~> 0.9) - cucumber (>= 1.3.19) - ffi (~> 1.9.10) - rspec-expectations (>= 2.99) - thor (~> 0.19) - builder (3.2.2) - childprocess (0.5.9) - ffi (~> 1.0, >= 1.0.11) - contracts (0.14.0) - cucumber (2.4.0) - builder (>= 2.1.2) - cucumber-core (~> 1.5.0) - cucumber-wire (~> 0.0.1) - diff-lcs (>= 1.1.3) - gherkin (~> 4.0) - multi_json (>= 1.7.5, < 2.0) - multi_test (>= 0.1.2) - cucumber-core (1.5.0) - gherkin (~> 4.0) - cucumber-wire (0.0.1) - diff-lcs (1.2.5) - diff_dirs (0.1.2) - ffi (1.9.14) - gherkin (4.0.0) - multi_json (1.12.1) - multi_test (0.1.2) - rspec-expectations (3.5.0) - diff-lcs (>= 1.2.0, < 2.0) - rspec-support (~> 3.5.0) - rspec-support (3.5.0) - thor (0.19.1) - -PLATFORMS - ruby - -DEPENDENCIES - aruba (~> 0.14.1) - diff_dirs (~> 0.1.2) - -BUNDLED WITH - 1.11.2 diff --git a/user/tests/accept/features/logging/log_config.feature b/user/tests/accept/features/logging/log_config.feature new file mode 100644 index 0000000000..2876e6fe9e --- /dev/null +++ b/user/tests/accept/features/logging/log_config.feature @@ -0,0 +1,228 @@ +Feature: Runtime logging configuration. See also user/tests/unit/logging.cpp + + +Background: + Given the application log_config_app + # Reset the device before running a scenario + And I reset the device + + +Scenario: Logging is disabled initially + Given I open Serial + And I open Serial1 + # Ask the device to generate a log message + When I send USB request + """ + { + "msg": "Test message 1" + } + """ + Then USB request should succeed + And Serial output should be empty + And Serial1 output should be empty + + +Scenario Outline: Enable logging on each of the serial interfaces + # Send configuration request to the device (REQUEST_TYPE_LOG_CONFIG) + When I send USB request with type 80 + """ + { + "cmd": "addHandler", + "id": "handler", + "hnd": { + "type": "StreamLogHandler" + }, + "strm": { + "type": "" + } + } + """ + And I open + And I send USB request + """ + { + "msg": "Test message" + } + """ + Then output should contain + """ + INFO: Test message + """ + Examples: + | Serial | + | Serial | + | Serial1 | + | USBSerial1 | + + +Scenario: Enable multiple log handlers with different filtering settings + Given I open Serial + And I open Serial1 + # This handler logs only messages that are at or above warning level + When I send USB request with type 80 + """ + { + "cmd": "addHandler", + "id": "handler1", + "hnd": { + "type": "StreamLogHandler" + }, + "strm": { + "type": "Serial" + }, + "lvl": "warn" + } + """ + # This handler also logs all application messages regardless of their logging level + And I send USB request with type 80 + """ + { + "cmd": "addHandler", + "id": "handler2", + "hnd": { + "type": "StreamLogHandler" + }, + "strm": { + "type": "Serial1", + }, + "filt": [ + { + "app": "all" + } + ], + "lvl": "warn", + } + """ + And I send USB request + """ + { + "msg": "Test message 1", + "level": "info", + "cat": "system" + } + """ + Then USB request should succeed + And Serial output should be empty + And Serial1 output should be empty + When I send USB request + """ + { + "msg": "Test message 2", + "level": "info", + "cat": "app" + } + """ + Then Serial output should be empty + And Serial1 output should contain + """ + INFO: Test message 2 + """ + When I send USB request + """ + { + "msg": "Test message 3", + "level": "warn", + "cat": "app" + } + """ + Then Serial output should contain + """ + WARN: Test message 3 + """ + And Serial1 output should contain + """ + WARN: Test message 3 + """ + + +Scenario: Add, remove and enumerate active log handlers + When I send USB request with type 80 + """ + { + "cmd": "enumHandlers", + } + """ + Then USB reply should be + """ + [] + """ + When I send USB request with type 80 + """ + { + "cmd": "addHandler", + "id": "handler1", + "hnd": { + "type": "StreamLogHandler" + }, + "strm": { + "type": "Serial", + } + } + """ + And I send USB request with type 80 + """ + { + "cmd": "enumHandlers", + } + """ + Then USB reply should be + """ + ["handler1"] + """ + When I send USB request with type 80 + """ + { + "cmd": "addHandler", + "id": "handler2", + "hnd": { + "type": "StreamLogHandler" + }, + "strm": { + "type": "Serial1", + } + } + """ + And I send USB request with type 80 + """ + { + "cmd": "enumHandlers", + } + """ + Then USB reply should be + """ + ["handler1","handler2"] + """ + When I send USB request with type 80 + """ + { + "cmd": "removeHandler", + "id": "handler1" + } + """ + And I send USB request with type 80 + """ + { + "cmd": "enumHandlers", + } + """ + Then USB reply should be + """ + ["handler2"] + """ + When I send USB request with type 80 + """ + { + "cmd": "removeHandler", + "id": "handler2" + } + """ + And I send USB request with type 80 + """ + { + "cmd": "enumHandlers", + } + """ + Then USB reply should be + """ + [] + """ diff --git a/user/tests/accept/features/logging/log_config_app/app.cpp b/user/tests/accept/features/logging/log_config_app/app.cpp new file mode 100644 index 0000000000..46772947a3 --- /dev/null +++ b/user/tests/accept/features/logging/log_config_app/app.cpp @@ -0,0 +1,39 @@ +#include "application.h" + +SYSTEM_MODE(MANUAL) + +bool usb_request_custom_handler(char* buf, size_t bufSize, size_t reqSize, size_t* repSize) { + const char* msg = "Test message"; + const char* cat = "app"; // Category name + LogLevel level = LOG_LEVEL_INFO; + // Parse JSON request + JSONObjectIterator it(JSONValue::parse(buf, reqSize)); + while (it.next()) { + if (it.name() == "msg") { + msg = (const char*)it.value().toString(); + } else if (it.name() == "cat") { + cat = (const char*)it.value().toString(); + } else if (it.name() == "level") { + JSONString s = it.value().toString(); + if (s == "trace") { + level = LOG_LEVEL_TRACE; + } else if (s == "info") { + level = LOG_LEVEL_INFO; + } else if (s == "warn") { + level = LOG_LEVEL_WARN; + } else if (s == "error") { + level = LOG_LEVEL_ERROR; + } + } + } + // Generate log message + Logger log(cat); + log(level, "%s", msg); + return true; +} + +void setup() { +} + +void loop() { +} diff --git a/user/tests/accept/features/step_definitions/build.rb b/user/tests/accept/features/step_definitions/build.rb new file mode 100644 index 0000000000..b69870d492 --- /dev/null +++ b/user/tests/accept/features/step_definitions/build.rb @@ -0,0 +1,5 @@ +Given(/^the application (.+)$/) do |app_dir| + feature_path = File.dirname(@current_scenario.location.file) + app_path = File.join(feature_path, app_dir) + Particle::Build.flash_app(app_path) +end diff --git a/user/tests/accept/features/step_definitions/device.rb b/user/tests/accept/features/step_definitions/device.rb new file mode 100644 index 0000000000..e03870e781 --- /dev/null +++ b/user/tests/accept/features/step_definitions/device.rb @@ -0,0 +1,3 @@ +When(/^I reset the device$/) do + Particle::Device.reset +end diff --git a/user/tests/accept/features/step_definitions/serial.rb b/user/tests/accept/features/step_definitions/serial.rb new file mode 100644 index 0000000000..fa734045fb --- /dev/null +++ b/user/tests/accept/features/step_definitions/serial.rb @@ -0,0 +1,34 @@ +serial = Particle::Serial.instance + +Given(/^I open (.*Serial.*)(?: with baud rate (\d+))?$/) do |port, baud| + baud ||= 9600 + serial.open(port, baud) +end + +When(/^I write to (.*Serial.*)$/) do |port, data| + serial.write(port, data) +end + +Then(/^(.*Serial.*) output should( not)? (be|contain|match|start with|end with)$/) do |port, neg, op, data| + if neg + serial.wait_while(port) do |d| + Particle::Util.should_not(op, d, data) + end + else + serial.wait_until(port) do |d| + Particle::Util.should(op, d, data) + end + end +end + +Then(/^(.*Serial.*) output should( not)? (be empty)$/) do |port, neg, op| + if neg + serial.wait_until(port) do |d| + Particle::Util.should_not(op, d) + end + else + serial.wait_while(port) do |d| + Particle::Util.should(op, d) + end + end +end diff --git a/user/tests/accept/features/step_definitions/usb.rb b/user/tests/accept/features/step_definitions/usb.rb new file mode 100644 index 0000000000..5a2c6120e9 --- /dev/null +++ b/user/tests/accept/features/step_definitions/usb.rb @@ -0,0 +1,35 @@ +usb = Particle::Usb.instance + +When(/^I send USB request(?: with type (\d+))?$/) do |type, data| + type ||= Particle::Usb::DEFAULT_REQUEST_TYPE + usb.send_request(type, data) +end + +Then(/^USB reply should( not)? (be|contain|match|start with|end with)$/) do |neg, op, data| + d = usb.take_reply + if neg + Particle::Util.should_not(op, d, data) + else + Particle::Util.should(op, d, data) + end +end + +Then(/^USB reply should( not)? (be empty)$/) do |neg, op| + d = usb.take_reply + if neg + Particle::Util.should_not(op, d) + else + Particle::Util.should(op, d) + end +end + +Then(/^USB request should( not)? (fail|succeed)$/) do |neg, op| + status = if op == 'fail' + !!neg + else + !neg + end + e = usb.last_error + raise e if e && status + expect(!e).to eq(status) +end diff --git a/user/tests/accept/features/step_definitions/util.rb b/user/tests/accept/features/step_definitions/util.rb new file mode 100644 index 0000000000..b9ee1024d6 --- /dev/null +++ b/user/tests/accept/features/step_definitions/util.rb @@ -0,0 +1,12 @@ +Given(/^I wait for (.+) (seconds|second|milliseconds|millisecond)$/) do |val, unit| + val = val.to_f + if unit == 'milliseconds' || unit == 'millisecond' + val /= 1000 + end + sleep(val) +end + +# Convert step arguments to integers where possible +Transform(/^(-?\d+)$/) do |val| + val.to_i +end diff --git a/user/tests/accept/features/support/build.rb b/user/tests/accept/features/support/build.rb new file mode 100644 index 0000000000..3b2c06468a --- /dev/null +++ b/user/tests/accept/features/support/build.rb @@ -0,0 +1,19 @@ +module Particle + module Build + class << self + # Last application path is cached in order to not flash the same application for every scenario + @last_app_path = nil + + def flash_app(app_path) + if app_path != @last_app_path + target_path = Util.cache_dir(File.join('build_target', app_path)) + Util.exec("flash_app -t #{target_path} #{app_path}") + @last_app_path = app_path + # Give the device some time to boot into the application + # TODO: Wait for specific device state instead of fixed delay + sleep(2) + end + end + end + end +end diff --git a/user/tests/accept/features/support/device.rb b/user/tests/accept/features/support/device.rb new file mode 100644 index 0000000000..ca20475e4a --- /dev/null +++ b/user/tests/accept/features/support/device.rb @@ -0,0 +1,12 @@ +module Particle + module Device + class << self + def reset + Util.exec("device_ctl reset") + # Give the device some time to boot into the application + # TODO: Wait for specific device state instead of fixed delay + sleep(2) + end + end + end +end diff --git a/user/tests/accept/features/support/env.rb b/user/tests/accept/features/support/env.rb index fb0a661b9f..669bf90f15 100644 --- a/user/tests/accept/features/support/env.rb +++ b/user/tests/accept/features/support/env.rb @@ -1 +1,36 @@ require 'aruba/cucumber' +require 'concurrent/atomics' +require 'em/pure_ruby' # Pure implementation is required by em-rubyserial + +# Runs EventMachine's event loop in background thread +class EventLoop + def initialize + started = Concurrent::Event.new + @thread = Thread.new do + EM.run do + started.set + end + end + started.wait + end + + def shutdown + EM.stop_event_loop + @thread.join + end +end + +event_loop = EventLoop.new + +at_exit do + event_loop.shutdown +end + +Before do |scenario| + @current_scenario = scenario +end + +After do |scenario| + Particle::Serial.instance.reset + Particle::Usb.instance.reset +end diff --git a/user/tests/accept/features/support/serial.rb b/user/tests/accept/features/support/serial.rb new file mode 100644 index 0000000000..b1e7d56ff4 --- /dev/null +++ b/user/tests/accept/features/support/serial.rb @@ -0,0 +1,148 @@ +require 'concurrent/synchronization' +require 'concurrent/utility/monotonic_time' +require 'em-rubyserial' +require 'singleton' + +module Particle + class SerialPort < EM::Connection + def initialize + @data = '' + @lock = Concurrent::Synchronization::Lock.new + end + + def close + close_connection_after_writing + end + + def write(data) + send_data(to_serial(data)) + end + + def wait_until(timeout, condition) + last_except = nil + # Keep calling provided block until it returns 'true' for current data + ok = @lock.wait_until(timeout) do + begin + condition.call(from_serial(@data)) + rescue Exception => e + last_except = e + false + end + end + unless ok + raise last_except if last_except # Rethrow last exception + raise "Serial output doesn't match expected data" # Generic error message + end + end + + def wait_while(timeout, condition) + # Keep calling provided block until it returns 'false' for current data + failed = @lock.wait_until(timeout) do + !condition.call(from_serial(@data)) + end + raise "Serial output doesn't match expected data" if failed # Generic error message + end + + # Called by EventMachine + def receive_data(data) + @lock.synchronize do + @data.concat(data) + @lock.broadcast # Notify waiters + end + end + + private + + def to_serial(data) + if data.ascii_only? + d = data.gsub("\n", "\r\n") # LF -> CRLF + d.concat("\r\n") unless d.end_with("\r\n") # Append new line sequence + d + else + data + end + end + + def from_serial(data) + if data.ascii_only? + d = data.gsub("\r\n", "\n") # CRLF -> LF + d.rstrip! # Strip trailing whitespace characters + d + else + data + end + end + end + + class Serial + include Singleton + + def initialize + @ports = { + 'Serial' => Util.env_var('PARTICLE_SERIAL_DEV'), + 'Serial1' => Util.env_var('PARTICLE_SERIAL1_DEV'), + 'USBSerial1' => Util.env_var('PARTICLE_USB_SERIAL1_DEV') + } + + @active_ports = {} + end + + def open(port, baud = 9600, data_bits = 8) + dev = @ports[port] + raise "Unknown serial port: #{port}" unless dev + p = @active_ports[port] + if p + p.close + @active_ports.delete(port) + end + # Certain ports, such as USBSerial1, may take some time to get registered at the host + wait_until_accessible(dev) + p = EM.open_serial(dev, baud, data_bits, SerialPort) + @active_ports[port] = p + end + + def close(port) + active_port(port).close + @active_ports.delete(port) + end + + def write(port, data) + active_port(port).write(data) + end + + def wait_until(port, timeout = 3, &condition) + active_port(port).wait_until(timeout, condition) + end + + def wait_while(port, timeout = 1, &condition) + active_port(port).wait_while(timeout, condition) + end + + def reset + # Close all ports + @active_ports.each_value do |p| + p.close + end + @active_ports.clear + end + + private + + def wait_until_accessible(file, timeout = 3) + if !File.exist?(file) || !File.readable?(file) || !File.writable?(file) + Timeout::timeout(timeout) do + loop do + sleep(0.1) + break if File.exist?(file) && File.readable?(file) && File.writable?(file) + end + end + end + end + + def active_port(port) + p = @active_ports[port] + raise "Serial port is not open: #{port}" unless p + p + end + end +end diff --git a/user/tests/accept/features/support/usb.rb b/user/tests/accept/features/support/usb.rb new file mode 100644 index 0000000000..60ac41d1e6 --- /dev/null +++ b/user/tests/accept/features/support/usb.rb @@ -0,0 +1,44 @@ +require 'singleton' +require 'hex_string' + +module Particle + class Usb + include Singleton + + DEFAULT_REQUEST_TYPE = 10 # USBRequestType::REQUEST_TYPE_CUSTOM + + def initialize + @reply = nil + @except = nil + end + + def send_request(type, data = '') + begin + data = data.to_hex_string(false) + data = Util.exec("send_usb_req -r 80 -v 0 -i #{type} -x #{data}") + @reply = data.to_byte_string + @except = nil + rescue Exception => e + @reply = nil + @except = e + end + end + + def take_reply + raise @except if @except # Rethrow last exception + raise "No reply data available" unless @reply + r = @reply + @reply = nil + r + end + + def last_error + @except + end + + def reset + @reply = nil + @except = nil + end + end +end diff --git a/user/tests/accept/features/support/util.rb b/user/tests/accept/features/support/util.rb new file mode 100644 index 0000000000..0867ecdebb --- /dev/null +++ b/user/tests/accept/features/support/util.rb @@ -0,0 +1,71 @@ +require 'rspec/matchers' +require 'open3' + +module Particle + CACHE_DIR = File.join(Dir.getwd, '.cache') + + module Util + class << self + include RSpec::Matchers + + def should(op, val1, val2 = nil) + case op + when 'be' + expect(val1).to eq(val2) + when 'contain' + expect(val1).to include(val2) + when 'match' + expect(val1).to match(val2) + when 'start with' + expect(val1).to start_with(val2) + when 'end with' + expect(val1).to end_with(val2) + when 'be empty' + expect(val1).to be_empty + else + raise "Unknown operation: #{op}" + end + end + + def should_not(op, val1, val2 = nil) + case op + when 'be' + expect(val1).not_to eq(val2) + when 'contain' + expect(val1).not_to include(val2) + when 'match' + expect(val1).not_to match(val2) + when 'start with' + expect(val1).not_to start_with(val2) + when 'end with' + expect(val1).not_to end_with(val2) + when 'be empty' + expect(val1).not_to be_empty + else + raise "Unknown operation: #{op}" + end + end + + def exec(cmd) + stdout, stderr, status = Open3.capture3(cmd) + raise "External command has finished with an error (exit code: #{status.exitstatus})\n#{stderr}" unless status.success? + stdout.rstrip + end + + def cache_dir(subdir) + path = CACHE_DIR + if subdir + path = File.join(path, subdir) + end + FileUtils.mkdir_p(path) + path + end + + def env_var(name) + val = ENV[name] + raise "Environment variable is not defined: #{name}" unless val + val + end + end + end +end diff --git a/user/tests/accept/init_env b/user/tests/accept/init_env new file mode 100644 index 0000000000..84fc4ae7a4 --- /dev/null +++ b/user/tests/accept/init_env @@ -0,0 +1,76 @@ +#!/bin/bash + +if [ $PARTICLE_TEST_ENV ]; then + return +fi + +warn() { + >&2 echo "Warning: $1" +} + +error() { + >&2 echo "Error: $1" + exit 1 +} + +require_tool() { + which $1 > /dev/null || error "'$1' is not installed" +} + +require_var() { + [ ${!1+x} ] || error "$1 is not defined" +} + +export -f warn error require_tool require_var + +require_var PLATFORM + +# USB vendor/product ID +if [ ! $USB_VENDOR_ID ] || [ ! $USB_PRODUCT_ID ]; then + case $PLATFORM in + core) + USB_VENDOR_ID=1d50 + USB_PRODUCT_ID=607d + ;; + photon) + USB_VENDOR_ID=2b04 + USB_PRODUCT_ID=c006 + ;; + p1) + USB_VENDOR_ID=2b04 + USB_PRODUCT_ID=d008 + ;; + electron) + USB_VENDOR_ID=2b04 + USB_PRODUCT_ID=d00a + ;; + *) + error "Unsupported platform: $PLATFORM" + ;; + esac + export USB_VENDOR_ID + export USB_PRODUCT_ID +fi + +# Primary serial over USB interface +if [ ! $PARTICLE_SERIAL_DEV ]; then + PARTICLE_SERIAL_DEV=/dev/ttyACM0 + warn "PARTICLE_SERIAL_DEV is not defined, using $PARTICLE_SERIAL_DEV (Serial)" + export PARTICLE_SERIAL_DEV +fi + +# UART adapter device +if [ ! $PARTICLE_SERIAL1_DEV ]; then + PARTICLE_SERIAL1_DEV=/dev/ttyUSB0 + warn "PARTICLE_SERIAL1_DEV is not defined, using $PARTICLE_SERIAL1_DEV (Serial1)" + export PARTICLE_SERIAL1_DEV +fi + +# Additional serial over USB interface +if [ ! $PARTICLE_USB_SERIAL1_DEV ]; then + PARTICLE_USB_SERIAL1_DEV=/dev/ttyACM1 + warn "PARTICLE_USB_SERIAL1_DEV is not defined, using $PARTICLE_USB_SERIAL1_DEV (USBSerial1)" + export PARTICLE_USB_SERIAL1_DEV +fi + +export PARTICLE_TEST_ENV=1 diff --git a/user/tests/accept/run b/user/tests/accept/run index 4a618d7ba9..1289a757ca 100755 --- a/user/tests/accept/run +++ b/user/tests/accept/run @@ -1,5 +1,11 @@ #!/bin/bash -DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )" -pushd $DIR > /dev/null -PATH=$DIR:$PATH cucumber features --expand --tags ~@wip $* -popd + +set -e + +cd $(dirname "$0") +this_dir=$(pwd) + +PATH="$this_dir/tools:$PATH" +source ./init_env + +cucumber features --expand --tags ~@wip $* diff --git a/user/tests/accept/tools/device_ctl b/user/tests/accept/tools/device_ctl new file mode 100755 index 0000000000..b08143f149 --- /dev/null +++ b/user/tests/accept/tools/device_ctl @@ -0,0 +1,52 @@ +#!/bin/bash + +set -e + +usage() { + echo "$(basename $0) reset" + echo "$(basename $0) mode " + exit 1 +} + +# See firmware's USBRequestType enum +REQ_RESET=40 +REQ_DFU=50 +REQ_SAFE=60 +REQ_LISTEN=70 + +send_usb_out_req() { + send_usb_req -d out -i $1 || true +} + +reset() { + send_usb_out_req $REQ_RESET +} + +mode() { + case $1 in + dfu) + send_usb_out_req $REQ_DFU + ;; + safe) + send_usb_out_req $REQ_SAFE + ;; + listen) + send_usb_out_req $REQ_LISTEN + ;; + *) + usage + ;; + esac +} + +case $1 in + reset) + reset + ;; + mode) + mode $2 + ;; + *) + usage + ;; +esac diff --git a/user/tests/accept/tools/flash_app b/user/tests/accept/tools/flash_app new file mode 100755 index 0000000000..8429bf502d --- /dev/null +++ b/user/tests/accept/tools/flash_app @@ -0,0 +1,51 @@ +#!/bin/bash + +set -e + +require_var PLATFORM + +usage() { + echo "$(basename $0) [options] " + echo "Options:" + echo "-t (directory for target files)" + exit 1 +} + +# Default parameters +target_dir= + +# Parse arguments +while getopts ":t:" opt; do + case $opt in + t) + target_dir="$OPTARG" + ;; + *) + usage + ;; + esac +done + +shift $((OPTIND-1)) + +# Path to this script +this_dir=$(cd $(dirname "$0") && pwd) + +# Path to firmware's main directory +main_dir=$(cd "$this_dir/../../../../main" && pwd) + +# Path to directory for target files +if [ "target_dir" ]; then + target_dir=$(cd "$target_dir" && pwd) + export TARGET_DIR="$target_dir" +fi + +# Path to application +app_dir="$1" +[ "app_dir" ] || error "Application directory is not specified" +app_dir=$(cd "$app_dir" && pwd) +export APPDIR="$app_dir" + +# Build and flash the application +cd "$main_dir" +make -s all program-dfu diff --git a/user/tests/accept/tools/send_usb_req b/user/tests/accept/tools/send_usb_req new file mode 100755 index 0000000000..c8475b8979 --- /dev/null +++ b/user/tests/accept/tools/send_usb_req @@ -0,0 +1,142 @@ +#!/bin/bash + +set -e + +require_tool usbtool +require_var USB_VENDOR_ID +require_var USB_PRODUCT_ID + +# Default parameters +usb_req=80 +usb_val=0 +usb_index=10 +req_type=reqrep +max_size=4096 +timeout=3000 +hex_flag= + +usage() { + echo "$(basename $0) [options] [data]" + echo "Options:" + echo "-r (request field; default: $usb_req)" + echo "-v (value field; default: $usb_val)" + echo "-i (index field; default: $usb_index)" + echo "-d (request type: in, out, reqrep; default: $req_type)" + echo "-n (maximum number of bytes to receive; default: $max_size)" + echo "-t (timeout in milliseconds; default: $timeout)" + echo "-x (use hex-encoded data format)" + exit 1 +} + +# Sends host-to-device request +send_out_req() { + if [ "$1" ]; then + data_arg="-d $1" + else + data_arg= + fi + usbtool -v 0x$USB_VENDOR_ID -p 0x$USB_PRODUCT_ID $data_arg control out vendor device $usb_req $usb_val $usb_index +} + +# Sends device-to-host request +send_in_req() { + size_arg="-n $max_size" + if [ $1 ]; then + size_arg="-n $1" + fi + usbtool -v 0x$USB_VENDOR_ID -p 0x$USB_PRODUCT_ID $size_arg control in vendor device $usb_req $usb_val $usb_index +} + +# Prints current UNIX time with nanosecond precision +timestamp() { + date "+%s.%N" +} + +# Returns 0 if first argument is less than second argument +less_than() { + return $(echo "$1 >= $2" | bc) +} + +# Parse arguments +while getopts ":r:v:i:d:n:t:x" opt; do + case $opt in + r) + usb_req=$OPTARG + ;; + v) + usb_val=$OPTARG + ;; + i) + usb_index=$OPTARG + ;; + d) + req_type=$OPTARG + ;; + n) + max_size=$OPTARG + ;; + t) + timeout=$OPTARG + ;; + x) + hex_flag=1 + ;; + *) + usage + ;; + esac +done + +shift $((OPTIND-1)) + +if [ $req_type != in ] && [ $req_type != out ] && [ $req_type != reqrep ]; then + error "Invalid request type: $req_type" +fi + +if [ $req_type == reqrep ] || [ $req_type == out ]; then + data="$1" + if [ "$data" ]; then + if [ ! $hex_flag ]; then + # "abc" -> "616263" + data=$(printf "$data" | xxd -p | tr -d '\n') + fi + # "616263" -> "0x61,0x62,0x63" + data=$(printf "$data" | fold -w 2 | paste -s -d , | sed 's/\([^,]*\)/0x\1/g') + fi + + # Send host-to-device request + send_out_req "$data" > /dev/null +fi + +if [ $req_type == reqrep ] || [ $req_type == in ]; then + if [ $req_type == reqrep ]; then + # Convert milliseconds to seconds + timeout=$(echo "scale=3;$timeout/1000" | bc) + time_end=$(echo "$(timestamp) + $timeout" | bc) + + # Keep sending device-to-host requests until a reply is received + while : ; do + sleep 0.1 + data=$(send_in_req 2>/dev/null) && break + if [ $max_size != 0 ]; then + # Empty reply data seems to require some special handling + data=$(send_in_req 0 2>/dev/null) && break + fi + less_than $(timestamp) $time_end || error "Request timeout" + done + else + # Send device-to-host request + data=$(send_in_req) + fi + + if [ "$data" ]; then + # "0x61 0x62 0x63" -> "616263" + data=$(printf "$data" | sed 's/ //g;s/0x//g') + if [ ! $hex_flag ]; then + # "616263" -> "abc" + data=$(printf "$data" | xxd -r -p) + fi + # Print reply data + echo "$data" + fi +fi diff --git a/user/tests/accept/tools/tty_read_line b/user/tests/accept/tools/tty_read_line new file mode 100755 index 0000000000..3d1dd08f5c --- /dev/null +++ b/user/tests/accept/tools/tty_read_line @@ -0,0 +1,71 @@ +#!/bin/bash + +set -e + +usage() { + echo "$(basename $0) [options] " + echo "Options:" + echo "-n (number of lines to read; default: 1)" + echo "-t (timeout in milliseconds)" + echo "-b " + exit 1 +} + +require_tool stty + +# Default parameters +lines=1 +timeout= +baud= + +# Parse arguments +while getopts ":n:t:b:" opt; do + case $opt in + n) + lines=$OPTARG + ;; + t) + timeout=$OPTARG + ;; + b) + baud=$OPTARG + ;; + *) + usage + ;; + esac +done + +shift $((OPTIND-1)) + +dev=$1 +if [ ! $dev ]; then + error "Device is not specified" +fi + +stty_cmd="stty -F" +if [ $(uname -s) == Darwin ]; then + stty_cmd="stty -f" +fi + +# Backup serial device settings +tty_conf=$($stty_cmd $dev -g) +trap "$stty_cmd $dev $tty_conf 2>/dev/null" EXIT + +# Set baud rate +$stty_cmd $dev $baud min 1 time 0 + +if [ $timeout ]; then + # Convert milliseconds to seconds + timeout=$(echo "scale=3;$timeout/1000" | bc) + timeout_arg="-t $timeout" +fi + +n=0 +while IFS= read $timeout_arg -r line; do + echo "$line" + n=$((n + 1)) + [ $n == $lines ] && break +done < $dev + +[ $n == $lines ] || error "Read error" diff --git a/user/tests/unit/logging.cpp b/user/tests/unit/logging.cpp index 7a69f24811..41b4388edf 100644 --- a/user/tests/unit/logging.cpp +++ b/user/tests/unit/logging.cpp @@ -1,24 +1,25 @@ -#include -#include +#define LOG_MODULE_CATEGORY "module" +#define LOG_INCLUDE_SOURCE_INFO 1 + +#include "spark_wiring_logging.h" +#include "service_debug.h" + +#include "tools/catch.h" +#include "tools/string.h" +#include "tools/stream.h" +#include "tools/random.h" + #include #include -#include #include - -#define CATCH_CONFIG_PREFIX_ALL -#include "catch.hpp" - -#define LOG_MODULE_CATEGORY "module" -#define LOG_INCLUDE_SOURCE_INFO -#include "spark_wiring_logging.h" -#include "service_debug.h" +#include #define CHECK_LOG_ATTR_FLAG(flag, value) \ do { \ LogAttributes attr = { 0 }; \ attr.flag = 1; \ - CATCH_CHECK(attr.flags == value); \ + CHECK(attr.flags == value); \ } while (false) // Source file's logging category @@ -30,9 +31,12 @@ using namespace spark; std::string fileName(const std::string &path); +class TestLogHandler; + class LogMessage { public: - LogMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) : + LogMessage(TestLogHandler &handler, const char *msg, LogLevel level, const char *category, const LogAttributes &attr) : + handler_(handler), level_(level) { if (msg) { msg_ = msg; @@ -61,63 +65,67 @@ class LogMessage { } const LogMessage& messageEquals(const std::string &msg) const { - CATCH_CHECK(msg_ == msg); + CHECK(msg_ == msg); return *this; } const LogMessage& levelEquals(LogLevel level) const { - CATCH_CHECK(level_ == level); + CHECK(level_ == level); return *this; } const LogMessage& categoryEquals(const std::string &category) const { - CATCH_CHECK(cat_ == category); + CHECK(cat_ == category); return *this; } // Default attributes const LogMessage& fileEquals(const std::string &file) const { - CATCH_CHECK(file_ == file); + CHECK(file_ == file); return *this; } const LogMessage& lineEquals(int line) const { - CATCH_CHECK(line_ == line); + CHECK(line_ == line); return *this; } const LogMessage& functionEquals(const std::string &func) const { - CATCH_CHECK(func_ == func); + CHECK(func_ == func); return *this; } const LogMessage& timeEquals(uint32_t time) const { - CATCH_CHECK(time_ == time); + CHECK(time_ == time); return *this; } // Additional attributes const LogMessage& codeEquals(intptr_t code) const { - CATCH_CHECK(code_ == code); + CHECK(code_ == code); return *this; } const LogMessage& hasCode(bool yes = true) const { - CATCH_CHECK((bool)code_ == yes); + CHECK((bool)code_ == yes); return *this; } const LogMessage& detailsEquals(const std::string &str) const { - CATCH_CHECK(detail_ == str); + CHECK(detail_ == str); return *this; } const LogMessage& hasDetails(bool yes = true) const { - CATCH_CHECK((bool)detail_ == yes); + CHECK((bool)detail_ == yes); return *this; } + LogMessage checkNext() const; + void checkAtEnd() const; + private: + TestLogHandler &handler_; boost::optional msg_, cat_, file_, func_, detail_; boost::optional code_; boost::optional time_; @@ -125,123 +133,316 @@ class LogMessage { LogLevel level_; }; +// Base class for test log handlers class TestLogHandler: public LogHandler { public: - explicit TestLogHandler(LogLevel level = LOG_LEVEL_ALL, const Filters &filters = {}): - LogHandler(level, filters) { - LogManager::instance()->addHandler(this); + TestLogHandler(LogLevel level, LogCategoryFilters filters, Print *stream) : + LogHandler(level, filters), + strm_(stream) { } - virtual ~TestLogHandler() { - LogManager::instance()->removeHandler(this); - } - - LogMessage next() { - CATCH_REQUIRE(!msgs_.empty()); + LogMessage checkNext() { + REQUIRE(!msgs_.empty()); const LogMessage m = msgs_.front(); msgs_.pop(); return m; } - bool hasNext() const { - return !msgs_.empty(); + void checkAtEnd() const { + REQUIRE(msgs_.empty()); } - const std::string& buffer() const { - return buf_; + bool hasNext() const { + return !msgs_.empty(); } - const TestLogHandler& bufferEquals(const std::string &str) const { - CATCH_CHECK(buf_ == str); - return *this; - } - - const TestLogHandler& bufferEndsWith(const std::string &str) const { - const std::string s = (buf_.size() >= str.size()) ? buf_.substr(buf_.size() - str.size(), str.size()) : str; - CATCH_CHECK(str == s); - return *this; + Print* stream() const { + return strm_; } protected: // spark::LogHandler virtual void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) override { - msgs_.push(LogMessage(msg, level, category, attr)); + msgs_.push(LogMessage(*this, msg, level, category, attr)); } virtual void write(const char *data, size_t size) override { - buf_.append(data, size); + if (strm_) { // Output stream is optional + strm_->write((const uint8_t*)data, size); + } } private: std::queue msgs_; - std::string buf_; + Print *strm_; +}; + +inline LogMessage LogMessage::checkNext() const { + return handler_.checkNext(); +} + +inline void LogMessage::checkAtEnd() const { + handler_.checkAtEnd(); +} + +// Log handler using its own output stream and registering itself automatically +class DefaultLogHandler: public TestLogHandler { +public: + explicit DefaultLogHandler(LogLevel level = LOG_LEVEL_ALL, LogCategoryFilters filters = {}) : + TestLogHandler(level, filters, &strm_) { + LogManager::instance()->addHandler(this); + } + + virtual ~DefaultLogHandler() { + LogManager::instance()->removeHandler(this); + } + + const test::OutputStream& stream() const { + return strm_; + } + +private: + test::OutputStream strm_; +}; + +// Log handler with additional parameters +class NamedLogHandler: public TestLogHandler { +public: + NamedLogHandler(std::string name, LogLevel level, LogCategoryFilters filters, Print *stream) : + TestLogHandler(level, filters, stream), + name_(name) { + ++s_count; + } + + virtual ~NamedLogHandler() { + --s_count; + } + + const std::string& name() const { + return name_; + } + + static size_t instanceCount() { + return s_count; + } + + // This class is non-copyable + NamedLogHandler(const NamedLogHandler&) = delete; + NamedLogHandler& operator=(const NamedLogHandler&) = delete; + +private: + std::string name_; + + static size_t s_count; }; // Log handler using compatibility callback class CompatLogHandler { public: explicit CompatLogHandler(LogLevel level = LOG_LEVEL_ALL) { - instance = this; + s_instance = this; set_logger_output(callback, level); } ~CompatLogHandler() { set_logger_output(nullptr, LOG_LEVEL_NONE); - instance = nullptr; + s_instance = nullptr; } - const std::string& buffer() const { - return buf_; + const test::OutputStream& stream() const { + return strm_; } - const CompatLogHandler& bufferEquals(const std::string &str) const { - CATCH_CHECK(buf_ == str); - return *this; +private: + test::OutputStream strm_; + + static CompatLogHandler *s_instance; + + static void callback(const char *str) { + s_instance->strm_.write((const uint8_t*)str, strlen(str)); } +}; - const CompatLogHandler& bufferEndsWith(const std::string &str) const { - const std::string s = (buf_.size() >= str.size()) ? buf_.substr(buf_.size() - str.size(), str.size()) : str; - CATCH_CHECK(str == s); - return *this; +// Mixin class registering log handler automatically +template +class ScopedLogHandler: public HandlerT { +public: + template + explicit ScopedLogHandler(ArgsT&&... args) : + HandlerT(std::forward(args)...) { + LogManager::instance()->addHandler(this); + } + + virtual ~ScopedLogHandler() { + LogManager::instance()->removeHandler(this); + } +}; + +class NamedLogHandlerFactory: public LogHandlerFactory { +public: + NamedLogHandlerFactory() { + LogManager::instance()->setHandlerFactory(this); + } + + virtual ~NamedLogHandlerFactory() { + // Restore default factory (destroys all active handlers) + LogManager::instance()->setHandlerFactory(DefaultLogHandlerFactory::instance()); + } + + virtual LogHandler* createHandler(const char *type, LogLevel level, LogCategoryFilters filters, Print *stream, + const JSONValue ¶ms) override { + if (strcmp(type, "NamedLogHandler") != 0) { + return nullptr; // Unsupported handler type + } + // Getting additional parameters + std::string name; + JSONObjectIterator it(params); + while (it.next()) { + if (it.name() == "name") { // Handler name + name = (const char*)it.value().toString(); + break; + } + } + if (handlers_.count(name)) { + return nullptr; // Duplicate handler name + } + NamedLogHandler *h = new NamedLogHandler(name, level, filters, stream); + handlers_.insert(std::make_pair(name, h)); + return h; + } + + virtual void destroyHandler(LogHandler *handler) override { + NamedLogHandler *h = dynamic_cast(handler); + if (h) { + handlers_.erase(h->name()); + delete h; + } else { + CATCH_WARN("NamedLogHandlerFactory: Unexpected handler type"); + } + } + + NamedLogHandler& handler(const std::string &name = std::string()) const { + const auto it = handlers_.find(name); + if (it == handlers_.end()) { + FAIL("NamedLogHandlerFactory: Unknown handler name: " << name); + } + return *it->second; + } + + bool hasHandler(const std::string &name = std::string()) const { + return handlers_.count(name); } private: - std::string buf_; + std::map handlers_; +}; - static CompatLogHandler *instance; +// Output stream with additional parameters +class NamedOutputStream: public test::OutputStream { +public: + explicit NamedOutputStream(std::string name) : + name_(name) { + ++s_count; + } - static void callback(const char *str) { - instance->buf_.append(str); + virtual ~NamedOutputStream() { + --s_count; + } + + const std::string& name() const { + return name_; } + + static size_t instanceCount() { + return s_count; + } + + // This class is non-copyable + NamedOutputStream(const NamedOutputStream&) = delete; + NamedOutputStream& operator=(const NamedOutputStream&) = delete; + +private: + std::string name_; + + static size_t s_count; }; -std::string randomString(size_t size = 0) { - static const std::string chars("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ1234567890!@#$%^&*()`~-_=+[{]}\\|;:'\",<.>/? "); - std::random_device rd; - if (!size) { - size = rd() % LOG_MAX_STRING_LENGTH + 1; +class NamedOutputStreamFactory: public OutputStreamFactory { +public: + NamedOutputStreamFactory() { + LogManager::instance()->setStreamFactory(this); } - std::uniform_int_distribution dist(0, chars.size() - 1); - std::string s; - s.reserve(size); - for (size_t i = 0; i < size; ++i) { - s += chars[dist(rd)]; + + virtual ~NamedOutputStreamFactory() { + // Restore default factory (destroys all active handlers) + LogManager::instance()->setStreamFactory(DefaultOutputStreamFactory::instance()); } - return s; -} -std::string randomBytes(size_t size = 0) { - std::random_device rd; - if (!size) { - size = rd() % (LOG_MAX_STRING_LENGTH / 2) + 1; + virtual Print* createStream(const char *type, const JSONValue ¶ms) override { + if (strcmp(type, "NamedOutputStream") != 0) { + return nullptr; // Unsupported stream type + } + // Getting additional parameters + std::string name; + JSONObjectIterator it(params); + while (it.next()) { + if (it.name() == "name") { // Stream name + name = (const char*)it.value().toString(); + break; + } + } + if (streams_.count(name)) { + return nullptr; // Duplicate stream name + } + NamedOutputStream *s = new NamedOutputStream(name); + streams_.insert(std::make_pair(name, s)); + return s; } - std::uniform_int_distribution dist(0, 255); - std::string s; - s.reserve(size); - for (size_t i = 0; i < size; ++i) { - s += (char)dist(rd); + + virtual void destroyStream(Print *stream) override { + NamedOutputStream *s = dynamic_cast(stream); + if (s) { + streams_.erase(s->name()); + delete s; + } else { + CATCH_WARN("NamedOutputStreamFactory: Unexpected stream type"); + } } - return s; + + NamedOutputStream& stream(const std::string &name = std::string()) const { + const auto it = streams_.find(name); + if (it == streams_.end()) { + FAIL("NamedOutputStreamFactory: Unknown stream name: " << name); + } + return *it->second; + } + + bool hasStream(const std::string &name = std::string()) const { + return streams_.count(name); + } + +private: + std::map streams_; +}; + +// Convenience wrapper for spark::logProcessConfigRequest() +bool processConfigRequest(const std::string &req, std::string *rep = nullptr, DataFormat fmt = DATA_FORMAT_JSON) { + char buf[1024]; + if (req.size() > sizeof(buf)) { + FAIL("processConfigRequest(): Too large request"); + } + memcpy(buf, req.data(), req.size()); + size_t repSize = 0; + if (!logProcessConfigRequest(buf, sizeof(buf), req.size(), &repSize, fmt)) { + return false; + } + if (rep) { + if (repSize > sizeof(buf)) { + FAIL("processConfigRequest(): Too large reply"); + } + *rep = std::string(buf, repSize); + } + return true; } std::string fileName(const std::string &path) { @@ -252,418 +453,415 @@ std::string fileName(const std::string &path) { return path; } -std::string toHex(const std::string &str) { - std::string s(boost::algorithm::hex(str)); - boost::algorithm::to_lower(s); // Logging library uses lower case - return s; -} +size_t NamedLogHandler::s_count = 0; +size_t NamedOutputStream::s_count = 0; -CompatLogHandler* CompatLogHandler::instance = nullptr; +CompatLogHandler* CompatLogHandler::s_instance = nullptr; const std::string SOURCE_FILE = fileName(__FILE__); const std::string SOURCE_CATEGORY = LOG_THIS_CATEGORY(); } // namespace -CATCH_TEST_CASE("Message logging") { - TestLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("default attributes") { +TEST_CASE("Message logging") { + DefaultLogHandler log(LOG_LEVEL_ALL); + SECTION("default attributes") { LOG(TRACE, "trace"); - log.next().messageEquals("trace").levelEquals(LOG_LEVEL_TRACE).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); + log.checkNext().messageEquals("trace").levelEquals(LOG_LEVEL_TRACE).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); LOG(INFO, "info"); - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); LOG(WARN, "warn"); - log.next().messageEquals("warn").levelEquals(LOG_LEVEL_WARN).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); + log.checkNext().messageEquals("warn").levelEquals(LOG_LEVEL_WARN).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); LOG(ERROR, "error"); - log.next().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); + log.checkNext().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); } - CATCH_SECTION("additional attributes") { + SECTION("additional attributes") { LOG(INFO, "info"); - log.next().hasCode(false).hasDetails(false); // No additional attributes + log.checkNext().hasCode(false).hasDetails(false); // No additional attributes LOG_ATTR(INFO, (code = -1, details = "details"), "info"); - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE) + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE) .codeEquals(-1).detailsEquals("details"); } - CATCH_SECTION("message formatting") { + SECTION("message formatting") { std::string s = ""; LOG(TRACE, "%s", s.c_str()); - log.next().messageEquals(""); - s = randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + log.checkNext().messageEquals(""); + s = test::randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG(INFO, "%s", s.c_str()); - log.next().messageEquals(s); - s = randomString(LOG_MAX_STRING_LENGTH); + log.checkNext().messageEquals(s); + s = test::randomString(LOG_MAX_STRING_LENGTH); LOG(WARN, "%s", s.c_str()); - log.next().messageEquals(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null - s = randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + log.checkNext().messageEquals(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null + s = test::randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG(ERROR, "%s", s.c_str()); - log.next().messageEquals(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); + log.checkNext().messageEquals(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); } - CATCH_SECTION("compatibility macros") { + SECTION("compatibility macros") { DEBUG("debug"); // Alias for LOG_DEBUG(TRACE, ...) #ifdef DEBUG_BUILD - log.next().messageEquals("debug").levelEquals(LOG_LEVEL_TRACE); + log.checkNext().messageEquals("debug").levelEquals(LOG_LEVEL_TRACE); #endif INFO("info"); // Alias for LOG(INFO, ...) - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO); + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO); WARN("warn"); // Alias for LOG(WARN, ...) - log.next().messageEquals("warn").levelEquals(LOG_LEVEL_WARN); + log.checkNext().messageEquals("warn").levelEquals(LOG_LEVEL_WARN); ERROR("error"); // Alias for LOG(ERROR, ...) - log.next().messageEquals("error").levelEquals(LOG_LEVEL_ERROR); + log.checkNext().messageEquals("error").levelEquals(LOG_LEVEL_ERROR); } } -CATCH_TEST_CASE("Message logging (compatibility callback)") { +TEST_CASE("Message logging (compatibility callback)") { CompatLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("default attributes") { + SECTION("default attributes") { LOG(TRACE, "trace"); - log.bufferEndsWith("TRACE: trace\r\n"); + check(log.stream()).endsWith("TRACE: trace\r\n"); LOG(INFO, "info"); - log.bufferEndsWith("INFO: info\r\n"); + check(log.stream()).endsWith("INFO: info\r\n"); LOG(WARN, "warn"); - log.bufferEndsWith("WARN: warn\r\n"); + check(log.stream()).endsWith("WARN: warn\r\n"); LOG(ERROR, "error"); - log.bufferEndsWith("ERROR: error\r\n"); - CATCH_CHECK(log.buffer().find(SOURCE_FILE) != std::string::npos); + check(log.stream()).endsWith("ERROR: error\r\n"); + check(log.stream()).contains(SOURCE_FILE); } - CATCH_SECTION("message formatting") { - std::string s = randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + SECTION("message formatting") { + std::string s = test::randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG(INFO, "%s", s.c_str()); - log.bufferEndsWith(s + "\r\n"); - s = randomString(LOG_MAX_STRING_LENGTH); + check(log.stream()).endsWith(s + "\r\n"); + s = test::randomString(LOG_MAX_STRING_LENGTH); LOG(WARN, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + "~\r\n"); // 1 character is reserved for term. null - s = randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + "~\r\n"); // 1 character is reserved for term. null + s = test::randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG(ERROR, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + "~\r\n"); + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + "~\r\n"); } } -CATCH_TEST_CASE("Direct logging") { - TestLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("write") { +TEST_CASE("Direct logging") { + DefaultLogHandler log(LOG_LEVEL_ALL); + SECTION("write") { std::string s = ""; LOG_WRITE(INFO, s.c_str(), s.size()); - log.bufferEquals(""); - s = randomString(); + check(log.stream()).isEmpty(); + s = test::randomString(1, 100); LOG_WRITE(WARN, s.c_str(), s.size()); - log.bufferEndsWith(s); - s = randomString(); + check(log.stream()).endsWith(s); + s = test::randomString(1, 100); LOG_PRINT(ERROR, s.c_str()); // Alias for LOG_WRITE(level, str, strlen(str)) - log.bufferEndsWith(s); + check(log.stream()).endsWith(s); } - CATCH_SECTION("printf") { + SECTION("printf") { std::string s = ""; LOG_PRINTF(TRACE, "%s", s.c_str()); - log.bufferEquals(""); - s = randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + check(log.stream()).isEmpty(); + s = test::randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG_PRINTF(INFO, "%s", s.c_str()); - log.bufferEquals(s); - s = randomString(LOG_MAX_STRING_LENGTH); + check(log.stream()).equals(s); + s = test::randomString(LOG_MAX_STRING_LENGTH); LOG_PRINTF(WARN, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null - s = randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null + s = test::randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG_PRINTF(ERROR, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); } - CATCH_SECTION("dump") { + SECTION("dump") { std::string s = ""; LOG_DUMP(TRACE, s.c_str(), s.size()); - log.bufferEquals(""); - s = randomBytes(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + check(log.stream()).isEmpty(); + s = test::randomBytes(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG_DUMP(INFO, s.c_str(), s.size()); - log.bufferEquals(toHex(s)); - s = randomBytes(LOG_MAX_STRING_LENGTH); + check(log.stream()).unhex().equals(s); + s = test::randomBytes(LOG_MAX_STRING_LENGTH); LOG_DUMP(WARN, s.c_str(), s.size()); - log.bufferEndsWith(toHex(s)); - s = randomBytes(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + check(log.stream()).unhex().endsWith(s); + s = test::randomBytes(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG_DUMP(ERROR, s.c_str(), s.size()); - log.bufferEndsWith(toHex(s)); + check(log.stream()).unhex().endsWith(s); } - CATCH_SECTION("compatibility macros") { - std::string s = randomString(); + SECTION("compatibility macros") { + std::string s = test::randomString(LOG_MAX_STRING_LENGTH / 2); DEBUG_D("%s", s.c_str()); // Alias for LOG_DEBUG_PRINTF(TRACE, ...) #ifdef DEBUG_BUILD - log.bufferEquals(s); + check(log.stream()).equals(s); #endif } } -// Copy-pase of above test case with TestLogHandler replaced with CompatLogHandler -CATCH_TEST_CASE("Direct logging (compatibility callback)") { +// Copy-pase of above test case with DefaultLogHandler replaced with CompatLogHandler +TEST_CASE("Direct logging (compatibility callback)") { CompatLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("write") { + SECTION("write") { std::string s = ""; LOG_WRITE(INFO, s.c_str(), s.size()); - log.bufferEquals(""); - s = randomString(); + check(log.stream()).isEmpty(); + s = test::randomString(1, 100); LOG_WRITE(WARN, s.c_str(), s.size()); - log.bufferEndsWith(s); - s = randomString(); + check(log.stream()).endsWith(s); + s = test::randomString(1, 100); LOG_PRINT(ERROR, s.c_str()); // Alias for LOG_WRITE(level, str, strlen(str)) - log.bufferEndsWith(s); + check(log.stream()).endsWith(s); } - CATCH_SECTION("printf") { + SECTION("printf") { std::string s = ""; LOG_PRINTF(TRACE, "%s", s.c_str()); - log.bufferEquals(""); - s = randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + check(log.stream()).isEmpty(); + s = test::randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG_PRINTF(INFO, "%s", s.c_str()); - log.bufferEquals(s); - s = randomString(LOG_MAX_STRING_LENGTH); + check(log.stream()).equals(s); + s = test::randomString(LOG_MAX_STRING_LENGTH); LOG_PRINTF(WARN, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null - s = randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); // 1 character is reserved for term. null + s = test::randomString(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG_PRINTF(ERROR, "%s", s.c_str()); - log.bufferEndsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); + check(log.stream()).endsWith(s.substr(0, LOG_MAX_STRING_LENGTH - 2) + '~'); } - CATCH_SECTION("dump") { + SECTION("dump") { std::string s = ""; LOG_DUMP(TRACE, s.c_str(), s.size()); - log.bufferEquals(""); - s = randomBytes(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer + check(log.stream()).isEmpty(); + s = test::randomBytes(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG_DUMP(INFO, s.c_str(), s.size()); - log.bufferEquals(toHex(s)); - s = randomBytes(LOG_MAX_STRING_LENGTH); + check(log.stream()).unhex().equals(s); + s = test::randomBytes(LOG_MAX_STRING_LENGTH); LOG_DUMP(WARN, s.c_str(), s.size()); - log.bufferEndsWith(toHex(s)); - s = randomBytes(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer + check(log.stream()).unhex().endsWith(s); + s = test::randomBytes(LOG_MAX_STRING_LENGTH * 3 / 2); // Larger than the internal buffer LOG_DUMP(ERROR, s.c_str(), s.size()); - log.bufferEndsWith(toHex(s)); + check(log.stream()).unhex().endsWith(s); } - CATCH_SECTION("compatibility macros") { - std::string s = randomString(); + SECTION("compatibility macros") { + std::string s = test::randomString(LOG_MAX_STRING_LENGTH / 2); DEBUG_D("%s", s.c_str()); // Alias for LOG_DEBUG_PRINTF(TRACE, ...) #ifdef DEBUG_BUILD - log.bufferEquals(s); + check(log.stream()).equals(s); #endif } } -CATCH_TEST_CASE("Basic filtering") { - CATCH_SECTION("warn") { - TestLogHandler log(LOG_LEVEL_WARN); // TRACE and INFO should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); +TEST_CASE("Basic filtering") { + SECTION("warn") { + DefaultLogHandler log(LOG_LEVEL_WARN); // TRACE and INFO should be filtered out + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("cd"); + check(log.stream()).equals("cd"); } - CATCH_SECTION("none") { - TestLogHandler log(LOG_LEVEL_NONE); // All levels should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && !LOG_ENABLED(ERROR))); + SECTION("none") { + DefaultLogHandler log(LOG_LEVEL_NONE); // All levels should be filtered out + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && !LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - CATCH_CHECK(!log.hasNext()); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals(""); + check(log.stream()).isEmpty(); } } -CATCH_TEST_CASE("Basic filtering (compatibility callback)") { +TEST_CASE("Basic filtering (compatibility callback)") { CompatLogHandler log(LOG_LEVEL_WARN); // TRACE and INFO should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); - CATCH_SECTION("trace") { + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + SECTION("trace") { LOG(TRACE, "message"); LOG_PRINT(TRACE, "print,"); LOG_PRINTF(TRACE, "%s", "printf,"); LOG_DUMP(TRACE, "\0", 1); - log.bufferEquals(""); + check(log.stream()).isEmpty(); } - CATCH_SECTION("info") { + SECTION("info") { LOG(INFO, "message"); LOG_PRINT(INFO, "print,"); LOG_PRINTF(INFO, "%s", "printf,"); LOG_DUMP(INFO, "\0", 1); - log.bufferEquals(""); + check(log.stream()).isEmpty(); } - CATCH_SECTION("warn") { + SECTION("warn") { LOG(WARN, "message"); LOG_PRINT(WARN, "print,"); LOG_PRINTF(WARN, "%s", "printf,"); LOG_DUMP(WARN, "\0", 1); - log.bufferEndsWith("WARN: message\r\nprint,printf,00"); + check(log.stream()).endsWith("WARN: message\r\nprint,printf,00"); } - CATCH_SECTION("error") { + SECTION("error") { LOG(ERROR, "message"); LOG_PRINT(ERROR, "print,"); LOG_PRINTF(ERROR, "%s", "printf,"); LOG_DUMP(ERROR, "\0", 1); - log.bufferEndsWith("ERROR: message\r\nprint,printf,00"); + check(log.stream()).endsWith("ERROR: message\r\nprint,printf,00"); } } -CATCH_TEST_CASE("Scoped category") { - TestLogHandler log(LOG_LEVEL_ALL); - CATCH_CHECK(LOG_THIS_CATEGORY() == SOURCE_CATEGORY); +TEST_CASE("Scoped category") { + DefaultLogHandler log(LOG_LEVEL_ALL); + CHECK(LOG_THIS_CATEGORY() == SOURCE_CATEGORY); LOG(INFO, ""); - log.next().categoryEquals(SOURCE_CATEGORY); + log.checkNext().categoryEquals(SOURCE_CATEGORY); { LOG_CATEGORY("scope"); - CATCH_CHECK(LOG_THIS_CATEGORY() == std::string("scope")); + CHECK(LOG_THIS_CATEGORY() == std::string("scope")); LOG(INFO, ""); - log.next().categoryEquals("scope"); + log.checkNext().categoryEquals("scope"); } - CATCH_CHECK(LOG_THIS_CATEGORY() == SOURCE_CATEGORY); + CHECK(LOG_THIS_CATEGORY() == SOURCE_CATEGORY); LOG(INFO, ""); - log.next().categoryEquals(SOURCE_CATEGORY); + log.checkNext().categoryEquals(SOURCE_CATEGORY); } -CATCH_TEST_CASE("Category filtering") { - TestLogHandler log(LOG_LEVEL_ERROR, { +TEST_CASE("Category filtering") { + DefaultLogHandler log(LOG_LEVEL_ERROR, { { "b.b", LOG_LEVEL_INFO }, { "a", LOG_LEVEL_WARN }, { "a.a.a", LOG_LEVEL_TRACE }, { "a.a", LOG_LEVEL_INFO } }); - CATCH_SECTION("a") { + SECTION("a") { LOG_CATEGORY("a"); // TRACE and INFO should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("cd"); + check(log.stream()).equals("cd"); } - CATCH_SECTION("a.a") { + SECTION("a.a") { LOG_CATEGORY("a.a"); // TRACE should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("bcd"); + check(log.stream()).equals("bcd"); } - CATCH_SECTION("a.a.a") { + SECTION("a.a.a") { LOG_CATEGORY("a.a.a"); // No messages should be filtered out - CATCH_CHECK((LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_TRACE); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_TRACE); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("abcd"); + check(log.stream()).equals("abcd"); } - CATCH_SECTION("a.x") { + SECTION("a.x") { LOG_CATEGORY("a.x"); // TRACE and INFO should be filtered out (according to filter set for "a" category) - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("cd"); + check(log.stream()).equals("cd"); } - CATCH_SECTION("a.a.x") { + SECTION("a.a.x") { LOG_CATEGORY("a.a.x"); // TRACE should be filtered out (according to filter set for "a.a" category) - CATCH_CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("bcd"); + check(log.stream()).equals("bcd"); } - CATCH_SECTION("a.a.a.x") { + SECTION("a.a.a.x") { LOG_CATEGORY("a.a.a.x"); // No messages should be filtered out (according to filter set for "a.a.a" category) - CATCH_CHECK((LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_TRACE); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_TRACE); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("abcd"); + check(log.stream()).equals("abcd"); } - CATCH_SECTION("b") { + SECTION("b") { LOG_CATEGORY("b"); // All levels except ERROR should be filtered out (default level) - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("d"); + check(log.stream()).equals("d"); } - CATCH_SECTION("b.x") { + SECTION("b.x") { LOG_CATEGORY("b.x"); // All levels except ERROR should be filtered out (default level) - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("d"); + check(log.stream()).equals("d"); } - CATCH_SECTION("b.b") { + SECTION("b.b") { LOG_CATEGORY("b.b"); // TRACE should be filtered out - CATCH_CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("bcd"); + check(log.stream()).equals("bcd"); } - CATCH_SECTION("b.b.x") { + SECTION("b.b.x") { LOG_CATEGORY("b.b.x"); // TRACE should be filtered out (according to filter set for "b.b" category) - CATCH_CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); LOG(TRACE, ""); LOG(INFO, ""); LOG(WARN, ""); LOG(ERROR, ""); - log.next().levelEquals(LOG_LEVEL_INFO); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_INFO); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); LOG_PRINT(TRACE, "a"); LOG_PRINT(INFO, "b"); LOG_PRINT(WARN, "c"); LOG_PRINT(ERROR, "d"); - log.bufferEquals("bcd"); + check(log.stream()).equals("bcd"); } } -CATCH_TEST_CASE("Malformed category name") { - TestLogHandler log(LOG_LEVEL_ERROR, { +TEST_CASE("Malformed category name") { + DefaultLogHandler log(LOG_LEVEL_ERROR, { { "a", LOG_LEVEL_WARN }, { "a.a", LOG_LEVEL_INFO } }); - CATCH_SECTION("empty") { + SECTION("empty") { LOG_CATEGORY(""); // All levels except ERROR should be filtered out (default level) - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); } - CATCH_SECTION(".") { + SECTION(".") { LOG_CATEGORY("."); // ditto - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); } - CATCH_SECTION(".a") { + SECTION(".a") { LOG_CATEGORY(".a"); // ditto - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && !LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); } - CATCH_SECTION("a.") { + SECTION("a.") { LOG_CATEGORY("a."); // TRACE and INFO should be filtered out (according to filter set for "a" category) - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); } - CATCH_SECTION("a..a") { + SECTION("a..a") { LOG_CATEGORY("a..a"); // ditto - CATCH_CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); + CHECK((!LOG_ENABLED(TRACE) && !LOG_ENABLED(INFO) && LOG_ENABLED(WARN) && LOG_ENABLED(ERROR))); } } -CATCH_TEST_CASE("Miscellaneous") { - CATCH_SECTION("exact category match") { - TestLogHandler log(LOG_LEVEL_ERROR, { +TEST_CASE("Miscellaneous") { + SECTION("exact category match") { + DefaultLogHandler log(LOG_LEVEL_ERROR, { { "aaa", LOG_LEVEL_TRACE }, { "aa", LOG_LEVEL_INFO }, { "a", LOG_LEVEL_WARN } }); - CATCH_CHECK(LOG_ENABLED_C(WARN, "a")); - CATCH_CHECK(LOG_ENABLED_C(INFO, "aa")); - CATCH_CHECK(LOG_ENABLED_C(TRACE, "aaa")); - CATCH_CHECK(LOG_ENABLED_C(ERROR, "x")); + CHECK(LOG_ENABLED_C(WARN, "a")); + CHECK(LOG_ENABLED_C(INFO, "aa")); + CHECK(LOG_ENABLED_C(TRACE, "aaa")); + CHECK(LOG_ENABLED_C(ERROR, "x")); } - CATCH_SECTION("attribute flag values") { + SECTION("attribute flag values") { CHECK_LOG_ATTR_FLAG(has_file, 0x01); CHECK_LOG_ATTR_FLAG(has_line, 0x02); CHECK_LOG_ATTR_FLAG(has_function, 0x04); @@ -674,41 +872,41 @@ CATCH_TEST_CASE("Miscellaneous") { } } -CATCH_TEST_CASE("Logger API") { - CATCH_SECTION("message logging") { - TestLogHandler log(LOG_LEVEL_ALL); +TEST_CASE("Logger API") { + SECTION("message logging") { + DefaultLogHandler log(LOG_LEVEL_ALL); Logger logger; // Uses module's category by default logger.trace("%s", "trace"); - log.next().messageEquals("trace").levelEquals(LOG_LEVEL_TRACE).categoryEquals(LOG_MODULE_CATEGORY); // No file info available + log.checkNext().messageEquals("trace").levelEquals(LOG_LEVEL_TRACE).categoryEquals(LOG_MODULE_CATEGORY); // No file info available logger.info("%s", "info"); - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); logger.warn("%s", "warn"); - log.next().messageEquals("warn").levelEquals(LOG_LEVEL_WARN).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("warn").levelEquals(LOG_LEVEL_WARN).categoryEquals(LOG_MODULE_CATEGORY); logger.error("%s", "error"); - log.next().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_MODULE_CATEGORY); logger.log(LOG_LEVEL_INFO, "%s", "info"); - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); logger.log("%s", "default"); // Uses default level - log.next().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); logger(LOG_LEVEL_INFO, "%s", "info"); // Alias for Logger::log(LogLevel, const char *fmt) - log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); logger("%s", "default"); // Alias for Logger::log(const char *fmt) - log.next().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); + log.checkNext().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); } - CATCH_SECTION("additional attributes") { - TestLogHandler log(LOG_LEVEL_ALL); + SECTION("additional attributes") { + DefaultLogHandler log(LOG_LEVEL_ALL); Logger logger; - logger.log(""); - log.next().hasCode(false).hasDetails(false); // No additional attributes + logger.log("%s", ""); + log.checkNext().hasCode(false).hasDetails(false); // No additional attributes // LogAttributes::code - logger.code(-1).log(""); - log.next().codeEquals(-1); + logger.code(-1).log("%s", ""); + log.checkNext().codeEquals(-1); // LogAttributes::details - logger.details("details").info(""); - log.next().detailsEquals("details"); + logger.details("details").info("%s", ""); + log.checkNext().detailsEquals("details"); } - CATCH_SECTION("direct logging") { - TestLogHandler log(LOG_LEVEL_ALL); + SECTION("direct logging") { + DefaultLogHandler log(LOG_LEVEL_ALL); Logger logger; logger.write(LOG_LEVEL_TRACE, "a", 1); logger.write("b", 1); // Uses default level @@ -718,40 +916,329 @@ CATCH_TEST_CASE("Logger API") { logger.printf("%s", "f"); logger.dump(LOG_LEVEL_ERROR, "\x01", 1); logger.dump("\x02", 1); - log.bufferEquals("abcdef0102"); + check(log.stream()).equals("abcdef0102"); } - CATCH_SECTION("basic filtering") { - TestLogHandler log(LOG_LEVEL_WARN); // TRACE and INFO should be filtered out + SECTION("basic filtering") { + DefaultLogHandler log(LOG_LEVEL_WARN); // TRACE and INFO should be filtered out Logger logger; - CATCH_CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); + CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); logger.trace("trace"); logger.info("info"); logger.warn("warn"); logger.error("error"); - log.next().levelEquals(LOG_LEVEL_WARN); - log.next().levelEquals(LOG_LEVEL_ERROR); - CATCH_CHECK(!log.hasNext()); + log.checkNext().levelEquals(LOG_LEVEL_WARN); + log.checkNext().levelEquals(LOG_LEVEL_ERROR); + CHECK(!log.hasNext()); logger.print(LOG_LEVEL_TRACE, "a"); logger.print(LOG_LEVEL_INFO, "b"); logger.print(LOG_LEVEL_WARN, "c"); logger.print(LOG_LEVEL_ERROR, "d"); - log.bufferEquals("cd"); + check(log.stream()).equals("cd"); } - CATCH_SECTION("category filtering") { + SECTION("category filtering") { // Only basic checks here - category filtering is tested in above test cases - TestLogHandler log(LOG_LEVEL_ERROR, { + DefaultLogHandler log(LOG_LEVEL_ERROR, { { "a", LOG_LEVEL_WARN }, { "a.b", LOG_LEVEL_INFO } }); - CATCH_SECTION("a") { + SECTION("a") { Logger logger("a"); // TRACE and INFO should be filtered out - CATCH_CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); + CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); } - CATCH_SECTION("a.b") { + SECTION("a.b") { Logger logger("a.b"); // TRACE should be filtered out - CATCH_CHECK((!logger.isTraceEnabled() && logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); + CHECK((!logger.isTraceEnabled() && logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); } - CATCH_SECTION("a.x") { + SECTION("a.x") { Logger logger("a.x"); // TRACE and INFO should be filtered out (according to filter set for "a" category) - CATCH_CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); + CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && logger.isWarnEnabled() && logger.isErrorEnabled())); } - CATCH_SECTION("x") { + SECTION("x") { Logger logger("x"); // All levels except ERROR should be filtered out (default level) - CATCH_CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && !logger.isWarnEnabled() && logger.isErrorEnabled())); + CHECK((!logger.isTraceEnabled() && !logger.isInfoEnabled() && !logger.isWarnEnabled() && logger.isErrorEnabled())); + } + } +} + +TEST_CASE("Message formatting") { + SECTION("level names") { + CHECK(LogHandler::levelName(LOG_LEVEL_TRACE) == std::string("TRACE")); + CHECK(LogHandler::levelName(LOG_LEVEL_INFO) == std::string("INFO")); + CHECK(LogHandler::levelName(LOG_LEVEL_WARN) == std::string("WARN")); + CHECK(LogHandler::levelName(LOG_LEVEL_ERROR) == std::string("ERROR")); + CHECK(LogHandler::levelName(LOG_LEVEL_PANIC) == std::string("PANIC")); + } + + SECTION("default formatting") { + test::OutputStream stream; + ScopedLogHandler handler(stream); + LOG_ATTR(INFO, (code = -1, details = "details"), "\"message\""); + // timestamp [category] file:line, function(): level: message [code = ..., details = ...] + check(stream).matches("\\d{10} \\[(.+)\\] (.+):\\d+, .+\\(\\): (.+): (.+) \\[code = (.+), details = (.+)\\]\r\n") + .at(0).equals(LOG_THIS_CATEGORY()) + .at(1).equals(SOURCE_FILE) + .at(2).equals("INFO") + .at(3).equals("\"message\"") + .at(4).equals("-1") + .at(5).equals("details"); + } + + SECTION("JSON formatting") { + test::OutputStream stream; + ScopedLogHandler handler(stream); + LOG_ATTR(INFO, (code = -1, details = "details"), "\"message\""); + // {"l": level, "m": message, "c": category, "f": file, "ln": line, "fn": function, "t": timestamp, "code": code, "detail": details} + check(stream).matches("{\"l\":\"(.+)\",\"m\":\"(.+)\",\"c\":\"(.+)\",\"f\":\"(.+)\",\"ln\":\\d+,\"fn\":\".+\",\"t\":\\d+,\"code\":(.+),\"detail\":\"(.+)\"}\r\n") + .at(0).equals("INFO") + .at(1).equals("\\\"message\\\"") // Special characters are escaped + .at(2).equals(LOG_THIS_CATEGORY()) + .at(3).equals(SOURCE_FILE) + .at(4).equals("-1") + .at(5).equals("details"); + } +} + +TEST_CASE("Configuration requests") { + NamedOutputStreamFactory streamFactory; + NamedLogHandlerFactory handlerFactory; + + SECTION("adding and removing message-based handler") { + // Add handler + std::string rep; + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," // Handler ID + "\"hnd\": {\"type\": \"NamedLogHandler\"}" // Handler settings + "}", &rep)); + CHECK(rep.empty()); // No reply data expected + CHECK(handlerFactory.handler().stream() == nullptr); // No output stream + CHECK(!streamFactory.hasStream()); + // Enumerate handlers + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[\"1\"]"); + // Do some logging + LOG(TRACE, ""); // Ignored by default + LOG(INFO, ""); + handlerFactory.handler().checkNext().levelEquals(LOG_LEVEL_INFO); + // Remove handler + REQUIRE(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"1\"}", &rep)); + CHECK(rep.empty()); // No reply data expected + CHECK(!handlerFactory.hasHandler()); + // Enumerate handlers + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[]"); // No active handlers + } + + SECTION("adding and removing stream-based handler") { + // Add handler + std::string rep; + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," // Handler ID + "\"hnd\": {\"type\": \"NamedLogHandler\"}," // Handler settings + "\"strm\": {\"type\": \"NamedOutputStream\"}" // Stream settings + "}", &rep)); + CHECK(rep.empty()); // No reply data expected + CHECK(handlerFactory.hasHandler()); + CHECK(streamFactory.hasStream()); + // Enumerate handlers + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[\"1\"]"); + // Do some logging + LOG(TRACE, ""); LOG_PRINT(TRACE, "trace"); // Ignored by default + LOG(INFO, ""); LOG_PRINT(INFO, "info"); + handlerFactory.handler().checkNext().levelEquals(LOG_LEVEL_INFO); + streamFactory.stream().check().equals("info"); + // Remove handler + REQUIRE(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"1\"}", &rep)); + CHECK(rep.empty()); // No reply data expected + CHECK(!handlerFactory.hasHandler()); + CHECK(!streamFactory.hasStream()); + // Enumerate handlers + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[]"); // No active handlers + } + + SECTION("handler- and stream-specific parameters") { + // Add handler + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"The Handler\"}}," // Handler name + "\"strm\": {\"type\": \"NamedOutputStream\", \"param\": {\"name\": \"The Stream\"}}" // Stream name + "}")); + CHECK(handlerFactory.hasHandler("The Handler")); + CHECK(streamFactory.hasStream("The Stream")); + // Remove handler + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"1\"}")); + } + + SECTION("adding multiple handlers with different settings") { + // Add handlers + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"a\"}}," + "\"lvl\": \"all\"" // LOG_LEVEL_ALL + "}")); + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"2\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"b\"}}," + "\"lvl\": \"info\"" // LOG_LEVEL_INFO + "}")); + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"3\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"c\"}}," + "\"lvl\": \"warn\"" // LOG_LEVEL_WARN + "}")); + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"4\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"d\"}}," + "\"lvl\": \"error\"," // LOG_LEVEL_ERROR (default level) + "\"filt\": [" + "{\"test\": \"trace\"}" // LOG_LEVEL_TRACE + "]}")); + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"5\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"e\"}}," + "\"lvl\": \"none\"" // LOG_LEVEL_NONE + "}")); + std::string rep; + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[\"1\",\"2\",\"3\",\"4\",\"5\"]"); + CHECK(handlerFactory.hasHandler("a")); + CHECK(handlerFactory.hasHandler("b")); + CHECK(handlerFactory.hasHandler("c")); + CHECK(handlerFactory.hasHandler("d")); + CHECK(handlerFactory.hasHandler("e")); + // Do some logging + LOG_C(TRACE, "test", ""); // Specifying category name explicitly + LOG(TRACE, ""); + LOG(INFO, ""); + LOG(WARN, ""); + LOG(ERROR, ""); + handlerFactory.handler("a") + .checkNext().levelEquals(LOG_LEVEL_TRACE).categoryEquals("test") + .checkNext().levelEquals(LOG_LEVEL_TRACE) + .checkNext().levelEquals(LOG_LEVEL_INFO) + .checkNext().levelEquals(LOG_LEVEL_WARN) + .checkNext().levelEquals(LOG_LEVEL_ERROR) + .checkAtEnd(); + handlerFactory.handler("b") + .checkNext().levelEquals(LOG_LEVEL_INFO) + .checkNext().levelEquals(LOG_LEVEL_WARN) + .checkNext().levelEquals(LOG_LEVEL_ERROR) + .checkAtEnd(); + handlerFactory.handler("c") + .checkNext().levelEquals(LOG_LEVEL_WARN) + .checkNext().levelEquals(LOG_LEVEL_ERROR) + .checkAtEnd(); + handlerFactory.handler("d") + .checkNext().levelEquals(LOG_LEVEL_TRACE).categoryEquals("test") + .checkNext().levelEquals(LOG_LEVEL_ERROR) + .checkAtEnd(); + handlerFactory.handler("e").checkAtEnd(); + // Remove handlers + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"1\"}")); + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"2\"}")); + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"3\"}")); + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"4\"}")); + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"5\"}")); + } + + SECTION("replacing handler") { + // Add handler + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"a\"}}" + "}")); + std::string rep; + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[\"1\"]"); + CHECK(handlerFactory.hasHandler("a")); + // Add another handler with the same ID + REQUIRE(processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\", \"param\": {\"name\": \"b\"}}" // a -> b + "}")); + REQUIRE(processConfigRequest("{\"cmd\": \"enumHandlers\"}", &rep)); + CHECK(rep == "[\"1\"]"); + CHECK(!handlerFactory.hasHandler("a")); + CHECK(handlerFactory.hasHandler("b")); // a -> b + // Remove handler + CHECK(processConfigRequest("{\"cmd\": \"removeHandler\", \"id\": \"1\"}")); + } + + SECTION("error handling and other checks") { + SECTION("too small buffer for reply data") { + char buf[] = "{\"cmd\": \"enumHandlers\"}"; + size_t repSize = 0; + REQUIRE(logProcessConfigRequest(buf, // Buffer used for request and reply data + 0, // Maximum size allowed for reply data + strlen(buf), // Request size + &repSize, // Actual size of reply data + DATA_FORMAT_JSON)); // Data format + CHECK(repSize == strlen("[]")); + CHECK(strncmp(buf, "[]", 2) != 0); + } + SECTION("unsupported handler type") { + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"DummyLogHandler\"}," + "\"strm\": {\"type\": \"NamedOutputStream\"}" + "}")); + } + SECTION("unsupported stream type") { + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\"}," + "\"strm\": {\"type\": \"DummyOutputStream\"}" + "}"));; + } + SECTION("missing or invalid parameters") { + SECTION("cmd") { + CHECK(!processConfigRequest("{" + "\"id\": \"1\"" + "}")); // Missing command name + CHECK(!processConfigRequest("{" + "\"cmd\": \"resetHandler\"" // Unsupported command + "\"id\": \"1\"" + "}")); + } + SECTION("addHandler") { + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"hnd\": {\"type\": \"NamedLogHandler\"}," + "}")); // Missing handler ID + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"param\": {\"name\": \"a\"}}" + "}")); // Missing handler type + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\"}," + "\"lvl\": \"debug\"" // Invalid level name + "}")); + CHECK(!processConfigRequest("{" + "\"cmd\": \"addHandler\"," + "\"id\": \"1\"," + "\"hnd\": {\"type\": \"NamedLogHandler\"}," + "\"filt\": [" + "{\"\": \"trace\"}" // Empty category name + "]}")); + } + SECTION("removeHandler") { + CHECK(!processConfigRequest("{" + "\"cmd\": \"removeHandler\"," + "}")); // Missing handler ID + } } } + + CHECK(NamedOutputStream::instanceCount() == 0); + CHECK(NamedLogHandler::instanceCount() == 0); } diff --git a/wiring/inc/debug_output_handler.h b/wiring/inc/debug_output_handler.h index 99801d5dd1..369a5665bc 100644 --- a/wiring/inc/debug_output_handler.h +++ b/wiring/inc/debug_output_handler.h @@ -28,13 +28,13 @@ namespace spark { class SerialLogHandler: public StreamLogHandler { public: - explicit SerialLogHandler(LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit SerialLogHandler(LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : StreamLogHandler(Serial, level, filters) { Serial.begin(); LogManager::instance()->addHandler(this); } - explicit SerialLogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit SerialLogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : StreamLogHandler(Serial, level, filters) { Serial.begin(baud); LogManager::instance()->addHandler(this); @@ -48,11 +48,11 @@ class SerialLogHandler: public StreamLogHandler { class Serial1LogHandler: public StreamLogHandler { public: - explicit Serial1LogHandler(LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit Serial1LogHandler(LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : Serial1LogHandler(9600, level, filters) { } - explicit Serial1LogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit Serial1LogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : StreamLogHandler(Serial1, level, filters) { Serial1.begin(baud); LogManager::instance()->addHandler(this); @@ -67,13 +67,13 @@ class Serial1LogHandler: public StreamLogHandler { #if Wiring_USBSerial1 class USBSerial1LogHandler: public StreamLogHandler { public: - explicit USBSerial1LogHandler(LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit USBSerial1LogHandler(LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : StreamLogHandler(USBSerial1, level, filters) { USBSerial1.begin(); LogManager::instance()->addHandler(this); } - explicit USBSerial1LogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}) : + explicit USBSerial1LogHandler(int baud, LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}) : StreamLogHandler(USBSerial1, level, filters) { USBSerial1.begin(baud); LogManager::instance()->addHandler(this); diff --git a/wiring/inc/spark_wiring_logging.h b/wiring/inc/spark_wiring_logging.h index ad9c98e2b2..f73bb7bffc 100644 --- a/wiring/inc/spark_wiring_logging.h +++ b/wiring/inc/spark_wiring_logging.h @@ -18,18 +18,71 @@ #ifndef SPARK_WIRING_LOGGING_H #define SPARK_WIRING_LOGGING_H -#include -#include #include #include #include "logging.h" +#include "spark_wiring_json.h" #include "spark_wiring_print.h" +#include "spark_wiring_string.h" +#include "spark_wiring_thread.h" +#include "spark_wiring_vector.h" +#include "spark_wiring_platform.h" + +#if Wiring_LogConfig +#include "system_control.h" +#endif namespace spark { -class AttributedLogger; +class LogCategoryFilter; + +typedef Vector LogCategoryFilters; + +namespace detail { + +// Internal implementation +class LogFilter { +public: + explicit LogFilter(LogLevel level); + LogFilter(LogLevel level, LogCategoryFilters filters); + ~LogFilter(); + + LogLevel level() const; + LogLevel level(const char *category) const; + + // This class in non-copyable + LogFilter(const LogFilter&) = delete; + LogFilter& operator=(const LogFilter&) = delete; + +private: + struct Node; + + Vector cats_; // Category filter strings + Vector nodes_; // Lookup table + LogLevel level_; // Default level + + static int nodeIndex(const Vector &nodes, const char *name, size_t size, bool &found); +}; + +} // namespace spark::detail + +class LogCategoryFilter { +public: + LogCategoryFilter(String category, LogLevel level); + LogCategoryFilter(const char *category, LogLevel level); + LogCategoryFilter(const char *category, size_t length, LogLevel level); + + const char* category() const; + LogLevel level() const; + +private: + String cat_; + LogLevel level_; + + friend class detail::LogFilter; +}; /*! \brief Abstract log handler. @@ -43,36 +96,26 @@ class AttributedLogger; */ class LogHandler { public: - /*! - \brief Category filter. - - Specifies minimal logging level enabled for a matching category. - */ - typedef std::pair Filter; - /*! - \brief List of category filters. - */ - typedef std::initializer_list Filters; - + explicit LogHandler(LogLevel level = LOG_LEVEL_INFO); /*! \brief Constructor. \param level Default logging level. \param filters Category filters. */ - explicit LogHandler(LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}); + LogHandler(LogLevel level, LogCategoryFilters filters); /*! \brief Destructor. */ - virtual ~LogHandler(); + virtual ~LogHandler() = default; /*! \brief Returns default logging level. */ - LogLevel defaultLevel() const; + LogLevel level() const; /*! \brief Returns logging level enabled for specified category. \param category Category name. */ - LogLevel categoryLevel(const char *category) const; + LogLevel level(const char *category) const; /*! \brief Returns level name. \param level Logging level. @@ -83,6 +126,10 @@ class LogHandler { void message(const char *msg, LogLevel level, const char *category, const LogAttributes &attr); void write(const char *data, size_t size, LogLevel level, const char *category); + // This class is non-copyable + LogHandler(const LogHandler&) = delete; + LogHandler& operator=(const LogHandler&) = delete; + protected: /*! \brief Performs processing of a log message. @@ -104,10 +151,7 @@ class LogHandler { virtual void write(const char *data, size_t size); private: - struct FilterData; - - std::vector filters_; - LogLevel level_; + detail::LogFilter filter_; }; /*! @@ -117,22 +161,17 @@ class LogHandler { */ class StreamLogHandler: public LogHandler { public: - /*! - \brief Output stream type. - */ - typedef Print Stream; - /*! \brief Constructor. \param stream Output stream. \param level Default logging level. \param filters Category filters. */ - explicit StreamLogHandler(Stream &stream, LogLevel level = LOG_LEVEL_INFO, const Filters &filters = {}); + explicit StreamLogHandler(Print &stream, LogLevel level = LOG_LEVEL_INFO, LogCategoryFilters filters = {}); /*! \brief Returns output stream. */ - Stream* stream() const; + Print* stream() const; protected: /*! @@ -161,11 +200,35 @@ class StreamLogHandler: public LogHandler { This method is equivalent to `write(str, strlen(str))`. */ void write(const char *str); + /*! + \brief Writes character to output stream. + \param c Character. + */ + void write(char c); + /*! + \brief Formats string and writes it to output stream. + \param fmt Format string. + + This method is equivalent to `stream()->printf(fmt, ...)`. + */ + template + void printf(const char *fmt, ArgsT... args); private: - Stream *stream_; + Print *stream_; }; +class JSONStreamLogHandler: public StreamLogHandler { +public: + using StreamLogHandler::StreamLogHandler; + +protected: + virtual void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) override; + virtual void write(const char *data, size_t size) override; +}; + +class AttributedLogger; + /*! \brief Logger. @@ -321,6 +384,10 @@ class Logger { */ void operator()(LogLevel level, const char *fmt, ...) const __attribute__((format(printf, 3, 4))); + // This class is non-copyable + Logger(const Logger&) = delete; + Logger& operator=(const Logger&) = delete; + private: const char* const name_; // Category name @@ -368,11 +435,57 @@ class AttributedLogger { LogAttributes attr_; explicit AttributedLogger(const char *name); + AttributedLogger(const AttributedLogger&) = default; + void log(LogLevel level, const char *fmt, va_list args); + AttributedLogger& operator=(const AttributedLogger&) = default; + friend class Logger; }; +#if Wiring_LogConfig + +// NOTE: This is an experimental API and is subject to change +class LogHandlerFactory { +public: + virtual ~LogHandlerFactory() = default; + + virtual LogHandler* createHandler(const char *type, LogLevel level, LogCategoryFilters filters, Print *stream, + const JSONValue ¶ms) = 0; // TODO: Use some generic container or a buffer instead of JSONValue + virtual void destroyHandler(LogHandler *handler); +}; + +class DefaultLogHandlerFactory: public LogHandlerFactory { +public: + virtual LogHandler* createHandler(const char *type, LogLevel level, LogCategoryFilters filters, Print *stream, + const JSONValue ¶ms) override; + + static DefaultLogHandlerFactory* instance(); +}; + +// NOTE: This is an experimental API and is subject to change +class OutputStreamFactory { +public: + virtual ~OutputStreamFactory() = default; + + virtual Print* createStream(const char *type, const JSONValue ¶ms) = 0; + virtual void destroyStream(Print *stream); +}; + +class DefaultOutputStreamFactory: public OutputStreamFactory { +public: + virtual Print* createStream(const char *type, const JSONValue ¶ms) override; + virtual void destroyStream(Print *stream) override; + + static DefaultOutputStreamFactory* instance(); + +private: + static void getParams(const JSONValue ¶ms, int *baudRate); +}; + +#endif // Wiring_LogConfig + /*! \brief Log manager. @@ -382,27 +495,108 @@ class AttributedLogger { class LogManager { public: /*! - \brief Registers log handler globally. + \brief Destructor. + */ + ~LogManager(); + /*! + \brief Registers log handler. + \param handler Handler instance. + \return `false` in case of error. - Note that this method doesn't affect ownership over the handler object. + \note Log manager doesn't take ownership over the handler instance. */ - void addHandler(LogHandler *handler); + bool addHandler(LogHandler *handler); /*! \brief Unregisters log handler. + \param handler Handler instance. */ void removeHandler(LogHandler *handler); + +#if Wiring_LogConfig + + /*! + \brief Creates and registers a factory log handler. + + \param id Handler ID. + \param handlerType Handler type. + \param level Default logging level. + \param filters Category filters. + \param handlerParams Additional handler parameters. + \param streamType Stream type. + \param streamParams Additional stream parameters. + + \return `false` in case of error. + */ + bool addFactoryHandler(const char *id, const char *handlerType, LogLevel level, LogCategoryFilters filters, + const JSONValue &handlerParams, const char *streamType, const JSONValue &streamParams); + /*! + \brief Unregisters and destroys a factory log handler. + + \param id Handler ID. + */ + void removeFactoryHandler(const char *id); + /*! + \brief Enumerates active factory log handlers. + + \param callback Callback function invoked for each active handler. + \param data User data. + */ + void enumFactoryHandlers(void(*callback)(const char *id, void *data), void *data); + /*! + \brief Sets log handler factory. + + \param factory Factory instance. + + \note Log manager doesn't take ownership over the factory instance. + */ + void setHandlerFactory(LogHandlerFactory *factory); + /*! + \brief Sets output stream factory. + + \param factory Factory instance. + + \note Log manager doesn't take ownership over the factory instance. + */ + void setStreamFactory(OutputStreamFactory *factory); + +#endif // Wiring_LogConfig + /*! \brief Returns log manager's instance. */ static LogManager* instance(); + // This class is non-copyable + LogManager(const LogManager&) = delete; + LogManager& operator=(const LogManager&) = delete; + private: - std::vector handlers_; + struct FactoryHandler; + + Vector activeHandlers_; + +#if Wiring_LogConfig + Vector factoryHandlers_; + LogHandlerFactory *handlerFactory_; + OutputStreamFactory *streamFactory_; +#endif - // This class is instantiated via instance() method - LogManager() = default; +#if PLATFORM_THREADING + Mutex mutex_; // TODO: Use read-write lock? +#endif + + // This class can be instantiated only via instance() method + LogManager(); + +#if Wiring_LogConfig + void destroyFactoryHandler(const char *id); + void destroyFactoryHandlers(); +#endif + + static void setSystemCallbacks(); + static void resetSystemCallbacks(); // System callbacks static void logMessage(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved); @@ -410,6 +604,23 @@ class LogManager { static int logEnabled(int level, const char *category, void *reserved); }; +#if Wiring_LogConfig + +/*! + \brief Performs processing of a configuration request. + + \param buf Buffer. + \param reqData Buffer size. + \param reqSize Request data size. + \param repSize Reply data size. + \param fmt Data format. + + \return `false` in case of error. +*/ +bool logProcessConfigRequest(char *buf, size_t bufSize, size_t reqSize, size_t *repSize, DataFormat fmt); + +#endif // Wiring_LogConfig + /*! \brief Default logger instance. */ @@ -417,15 +628,64 @@ extern const Logger Log; } // namespace spark +// spark::detail::LogFilter +inline LogLevel spark::detail::LogFilter::level() const { + return level_; +} + +// spark::LogCategoryFilter +inline spark::LogCategoryFilter::LogCategoryFilter(String category, LogLevel level) : + cat_(category), + level_(level) { +} + +inline spark::LogCategoryFilter::LogCategoryFilter(const char *category, LogLevel level) : + cat_(category), + level_(level) { +} + +inline spark::LogCategoryFilter::LogCategoryFilter(const char *category, size_t length, LogLevel level) : + cat_(category, length), + level_(level) { +} + +inline const char* spark::LogCategoryFilter::category() const { + return cat_.c_str(); +} + +inline LogLevel spark::LogCategoryFilter::level() const { + return level_; +} + // spark::LogHandler +inline spark::LogHandler::LogHandler(LogLevel level) : + filter_(level) { +} + +inline spark::LogHandler::LogHandler(LogLevel level, LogCategoryFilters filters) : + filter_(level, filters) { +} + +inline LogLevel spark::LogHandler::level() const { + return filter_.level(); +} + +inline LogLevel spark::LogHandler::level(const char *category) const { + return filter_.level(category); +} + +inline const char* spark::LogHandler::levelName(LogLevel level) { + return log_level_name(level, nullptr); +} + inline void spark::LogHandler::message(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) { - if (level >= categoryLevel(category)) { + if (level >= filter_.level(category)) { logMessage(msg, level, category, attr); } } inline void spark::LogHandler::write(const char *data, size_t size, LogLevel level, const char *category) { - if (level >= categoryLevel(category)) { + if (level >= filter_.level(category)) { write(data, size); } } @@ -434,32 +694,38 @@ inline void spark::LogHandler::write(const char *data, size_t size) { // Default implementation does nothing } -inline LogLevel spark::LogHandler::defaultLevel() const { - return level_; -} - -inline const char* spark::LogHandler::levelName(LogLevel level) { - return log_level_name(level, nullptr); -} - // spark::StreamLogHandler -inline spark::StreamLogHandler::StreamLogHandler(Stream &stream, LogLevel level, const Filters &filters) : +inline spark::StreamLogHandler::StreamLogHandler(Print &stream, LogLevel level, LogCategoryFilters filters) : LogHandler(level, filters), stream_(&stream) { } -inline void spark::StreamLogHandler::write(const char *data, size_t size) { - stream_->write((const uint8_t*)data, size); +inline Print* spark::StreamLogHandler::stream() const { + return stream_; } -inline spark::StreamLogHandler::Stream* spark::StreamLogHandler::stream() const { - return stream_; +inline void spark::StreamLogHandler::write(const char *data, size_t size) { + stream_->write((const uint8_t*)data, size); } inline void spark::StreamLogHandler::write(const char *str) { write(str, strlen(str)); } +inline void spark::StreamLogHandler::write(char c) { + write(&c, 1); +} + +template +inline void spark::StreamLogHandler::printf(const char *fmt, ArgsT... args) { + stream_->printf(fmt, args...); +} + +// spark::JSONStreamLogHandler +inline void spark::JSONStreamLogHandler::write(const char *data, size_t size) { + // This handler doesn't support direct logging +} + // spark::Logger inline spark::Logger::Logger(const char *name) : name_(name) { @@ -669,4 +935,18 @@ inline void spark::AttributedLogger::log(LogLevel level, const char *fmt, va_lis log_message_v(level, name_, &attr_, nullptr, fmt, args); } +#if Wiring_LogConfig + +// spark::LogHandlerFactory +inline void spark::LogHandlerFactory::destroyHandler(LogHandler *handler) { + delete handler; +} + +// spark::OutputStreamFactory +inline void spark::OutputStreamFactory::destroyStream(Print *stream) { + delete stream; +} + +#endif // Wiring_LogConfig + #endif // SPARK_WIRING_LOGGING_H diff --git a/wiring/inc/spark_wiring_platform.h b/wiring/inc/spark_wiring_platform.h index 2ded3f8cbf..d64fbfec6e 100644 --- a/wiring/inc/spark_wiring_platform.h +++ b/wiring/inc/spark_wiring_platform.h @@ -25,6 +25,7 @@ #define Wiring_WiFi 1 #define Wiring_IPv6 0 #define Wiring_SPI1 1 +#define Wiring_LogConfig 1 // for testing purposes #endif #if PLATFORM_ID==4 // photon dev @@ -48,6 +49,7 @@ #define Wiring_USBSerial1 1 #define Wiring_Mouse 1 #define Wiring_Keyboard 1 +#define Wiring_LogConfig 1 #endif #if PLATFORM_ID==7 @@ -68,6 +70,7 @@ #define Wiring_USBSerial1 1 #define Wiring_Mouse 1 #define Wiring_Keyboard 1 +#define Wiring_LogConfig 1 #endif #if PLATFORM_ID==9 // ethernet @@ -89,6 +92,7 @@ #define Wiring_USBSerial1 1 #define Wiring_Mouse 1 #define Wiring_Keyboard 1 +#define Wiring_LogConfig 1 #endif #ifndef Wiring_SPI1 @@ -139,5 +143,9 @@ #define Wiring_USBSerial1 0 #endif +#ifndef Wiring_LogConfig +#define Wiring_LogConfig 0 +#endif + #endif /* SPARK_WIRING_PLATFORM_H */ diff --git a/wiring/inc/spark_wiring_thread.h b/wiring/inc/spark_wiring_thread.h index 639e7904b0..a86f70e3e6 100644 --- a/wiring/inc/spark_wiring_thread.h +++ b/wiring/inc/spark_wiring_thread.h @@ -183,7 +183,7 @@ class SingleThreadedSection { #define SINGLE_THREADED_SECTION() SingleThreadedSection __cs; #define SINGLE_THREADED_BLOCK() for (bool __todo = true; __todo; ) for (SingleThreadedSection __cs; __todo; __todo=0) -#define WITH_LOCK(lock) for (bool __todo = true; __todo;) for (std::lock_guard __lock##lock((lock)); __todo; __todo=0) +#define WITH_LOCK(lock) for (bool __todo = true; __todo;) for (std::lock_guard __lock((lock)); __todo; __todo=0) #define TRY_LOCK(lock) for (bool __todo = true; __todo; ) for (std::unique_lock::type> __lock##lock((lock), std::try_to_lock); __todo &= bool(__lock##lock); __todo=0) #else diff --git a/wiring/src/spark_wiring_logging.cpp b/wiring/src/spark_wiring_logging.cpp index 06e593fbdb..e135c6c6fc 100644 --- a/wiring/src/spark_wiring_logging.cpp +++ b/wiring/src/spark_wiring_logging.cpp @@ -15,14 +15,295 @@ * License along with this library; if not, see . */ +#ifndef _GNU_SOURCE +#define _GNU_SOURCE // for strchrnul() +#endif +#include + +#include "spark_wiring_logging.h" + #include #include -#include +#include -#include "spark_wiring_logging.h" +#include "spark_wiring_usbserial.h" +#include "spark_wiring_usartserial.h" namespace { +using namespace spark; + +#if Wiring_LogConfig + +/* + This class performs processing of configuration requests in JSON format. + + Adding log handler: + + { + "cmd": "addHandler", // Command name + "id": "handler1", // Handler ID + "hnd": { // Handler settings + "type": "JSONLogHandler", // Handler type + "param": { // Additional handler parameters + ... + } + }, + "strm": { // Stream settings + "type": "Serial1", // Stream type + "param": { // Additional stream parameters + ... + } + } + "filt": [ // Category filters + { + "app": "all" // Category name and logging level + } + ], + "lvl": "warn" // Default logging level + } + + Removing log handler: + + { + "cmd": "removeHandler", // Command name + "id": "handler1" // Handler ID + } + + Enumerating active log handlers: + + { + "cmd": "enumHandlers" // Command name + } + + Reply example: + + [ + "handler1", "handler2" + ] +*/ +class JSONRequestHandler { +public: + static bool process(char *buf, size_t bufSize, size_t reqSize, size_t *repSize) { + const JSONValue jsonReq = JSONValue::parse(buf, reqSize); + if (!jsonReq.isValid()) { + return false; // Parsing error + } + Request req; + if (!parseRequest(jsonReq, &req)) { + return false; + } + JSONBufferWriter writer(buf, bufSize); + if (!processRequest(req, writer)) { + return false; + } + if (repSize) { + *repSize = writer.dataSize(); + } + return true; + } + +private: + struct Object { + JSONString type; + JSONValue params; + }; + + struct Request { + Object handler, stream; + LogCategoryFilters filters; + JSONString cmd, id; + LogLevel level; + + Request() : + level(LOG_LEVEL_INFO) { // Default level + } + }; + + static bool parseRequest(const JSONValue &value, Request *req) { + JSONObjectIterator it(value); + while (it.next()) { + if (it.name() == "cmd") { // Command name + req->cmd = it.value().toString(); + } else if (it.name() == "id") { // Handler ID + req->id = it.value().toString(); + } else if (it.name() == "hnd") { // Handler settings + if (!parseObject(it.value(), &req->handler)) { + return false; + } + } else if (it.name() == "strm") { // Stream settings + if (!parseObject(it.value(), &req->stream)) { + return false; + } + } else if (it.name() == "filt") { // Category filters + if (!parseFilters(it.value(), &req->filters)) { + return false; + } + } else if (it.name() == "lvl") { // Default level + if (!parseLevel(it.value(), &req->level)) { + return false; + } + } + } + return true; + } + + static bool parseObject(const JSONValue &value, Object *object) { + JSONObjectIterator it(value); + while (it.next()) { + if (it.name() == "type") { // Object type + object->type = it.value().toString(); + } else if (it.name() == "param") { // Additional parameters + object->params = it.value(); + } + } + return true; + } + + static bool parseFilters(const JSONValue &value, LogCategoryFilters *filters) { + JSONArrayIterator it(value); + if (!filters->reserve(it.count())) { + return false; // Memory allocation error + } + while (it.next()) { + JSONString cat; + LogLevel level = LOG_LEVEL_INFO; // Default level + JSONObjectIterator it2(it.value()); + if (it2.next()) { + cat = it2.name(); + if (cat.isEmpty()) { + return false; + } + if (!parseLevel(it2.value(), &level)) { + return false; + } + } + filters->append(LogCategoryFilter((String)cat, level)); + } + return true; + } + + static bool parseLevel(const JSONValue &value, LogLevel *level) { + const JSONString name = value.toString(); + static struct { + const char *name; + LogLevel level; + } levels[] = { + { "none", LOG_LEVEL_NONE }, + { "trace", LOG_LEVEL_TRACE }, + { "info", LOG_LEVEL_INFO }, + { "warn", LOG_LEVEL_WARN }, + { "error", LOG_LEVEL_ERROR }, + { "panic", LOG_LEVEL_PANIC }, + { "all", LOG_LEVEL_ALL } + }; + static size_t n = sizeof(levels) / sizeof(levels[0]); + size_t i = 0; + for (; i < n; ++i) { + if (name == levels[i].name) { + break; + } + } + if (i == n) { + return false; // Invalid level name + } + *level = levels[i].level; + return true; + } + + static bool processRequest(Request &req, JSONWriter &writer) { + if (req.cmd == "addHandler") { + return addHandler(req, writer); + } else if (req.cmd == "removeHandler") { + return removeHandler(req, writer); + } else if (req.cmd == "enumHandlers") { + return enumHandlers(req, writer); + } else { + return false; // Unsupported request + } + } + + static bool addHandler(Request &req, JSONWriter&) { + if (req.id.isEmpty() || req.handler.type.isEmpty()) { + return false; + } + const char* const strmType = !req.stream.type.isEmpty() ? (const char*)req.stream.type : nullptr; + return logManager()->addFactoryHandler((const char*)req.id, (const char*)req.handler.type, req.level, req.filters, + req.handler.params, strmType, req.stream.params); + } + + static bool removeHandler(Request &req, JSONWriter&) { + if (req.id.isEmpty()) { + return false; + } + logManager()->removeFactoryHandler((const char*)req.id); + return true; + } + + static bool enumHandlers(Request &req, JSONWriter &writer) { + writer.beginArray(); + logManager()->enumFactoryHandlers(enumHandlersCallback, &writer); + writer.endArray(); + return true; + } + + static void enumHandlersCallback(const char *id, void *data) { + JSONWriter *writer = static_cast(data); + writer->value(id); + } + + static LogManager* logManager() { + return LogManager::instance(); + } +}; + +// Custom deleter for std::unique_ptr +template +struct FactoryDeleter { + FactoryDeleter() : factory(nullptr) { + } + + FactoryDeleter(FactoryT *factory) : factory(factory) { + } + + void operator()(T *ptr) { + if (ptr) { + (factory->*destroy)(ptr); + } + } + + FactoryT *factory; +}; + +typedef FactoryDeleter LogHandlerFactoryDeleter; +typedef FactoryDeleter OutputStreamFactoryDeleter; + +#endif // Wiring_LogConfig + +#if PLATFORM_ID == 3 +// GCC on some platforms doesn't provide strchrnul() +inline const char* strchrnul(const char *s, char c) { + while (*s && *s != c) { + ++s; + } + return s; +} +#endif + +// Iterates over subcategory names separated by '.' character +const char* nextSubcategoryName(const char* &category, size_t &size) { + const char *s = strchrnul(category, '.'); + size = s - category; + if (size) { + if (*s) { + ++s; + } + std::swap(s, category); + return s; + } + return nullptr; +} + const char* extractFileName(const char *s) { const char *s1 = strrchr(s, '/'); if (s1) { @@ -47,27 +328,13 @@ const char* extractFuncName(const char *s, size_t *size) { } // namespace // Default logger instance. This code is compiled as part of the wiring library which has its own -// category name specified at module level, so here we have to use "app" category name explicitly +// category name specified at module level, so here we use "app" category name explicitly const spark::Logger spark::Log("app"); -// spark::LogHandler -struct spark::LogHandler::FilterData { - const char *name; // Subcategory name - size_t size; // Name length - int level; // Logging level (-1 if not specified for this node) - std::vector filters; // Children nodes - - FilterData(const char *name, size_t size) : - name(name), - size(size), - level(-1) { - } -}; - /* - This method builds prefix tree based on the list of filter strings. Every node of the tree - contains subcategory name and, optionally, logging level - if node matches complete filter - string. For example, given following filters: + LogFilter instance maintains a prefix tree based on a list of category filter strings. Every + node of the tree contains a subcategory name and, optionally, a logging level - if node matches + complete filter string. For example, given the following filters: a (error) a.b.c (trace) @@ -75,7 +342,7 @@ struct spark::LogHandler::FilterData { aa (error) aa.b (warn) - The code builds following prefix tree: + LogFilter builds the following prefix tree: | |- a (error) -- b - c (trace) @@ -84,180 +351,338 @@ struct spark::LogHandler::FilterData { | `- aa (error) - b (warn) */ -spark::LogHandler::LogHandler(LogLevel level, const Filters &filters) : + +// spark::detail::LogFilter +struct spark::detail::LogFilter::Node { + const char *name; // Subcategory name + uint16_t size; // Name length + int16_t level; // Logging level (-1 if not specified for this node) + Vector nodes; // Children nodes + + Node(const char *name, uint16_t size) : + name(name), + size(size), + level(-1) { + } +}; + +spark::detail::LogFilter::LogFilter(LogLevel level) : level_(level) { - for (auto it = filters.begin(); it != filters.end(); ++it) { - const char* const category = it->first; - const LogLevel level = it->second; - std::vector *filters = &filters_; // Root nodes - size_t pos = 0; - for (size_t i = 0;; ++i) { - if (category[i] && category[i] != '.') { // Category name separator - continue; - } - const size_t size = i - pos; - if (!size) { - break; // Invalid category name - } - const char* const name = category + pos; - // Use binary search to find existent node or position for new node +} + +spark::detail::LogFilter::LogFilter(LogLevel level, LogCategoryFilters filters) : + level_(LOG_LEVEL_NONE) { // Fallback level that will be used in case of construction errors + // Store category names + Vector cats; + if (!cats.reserve(filters.size())) { + return; + } + for (LogCategoryFilter &filter: filters) { + cats.append(std::move(filter.cat_)); + } + // Process category filters + Vector nodes; + for (int i = 0; i < cats.size(); ++i) { + const char *category = cats.at(i).c_str(); + if (!category) { + continue; // Invalid usage or string allocation error + } + Vector *pNodes = &nodes; // Root nodes + const char *name = nullptr; // Subcategory name + size_t size = 0; // Name length + while ((name = nextSubcategoryName(category, size))) { bool found = false; - auto it = std::lower_bound(filters->begin(), filters->end(), std::make_pair(name, size), - [&found](const FilterData &filter, const std::pair &value) { - const int cmp = std::strncmp(filter.name, value.first, std::min(filter.size, value.second)); - if (cmp == 0) { - if (filter.size == value.second) { - found = true; - } - return filter.size < value.second; - } - return cmp < 0; - }); - if (!found) { - it = filters->insert(it, FilterData(name, size)); // Add node + const int index = nodeIndex(*pNodes, name, size, found); + if (!found && !pNodes->insert(index, Node(name, size))) { // Add node + return; } - if (!category[i]) { - it->level = level; - break; + Node &node = pNodes->at(index); + if (!*category) { // Check if it's last subcategory + node.level = filters.at(i).level_; } - filters = &it->filters; - pos = i + 1; + pNodes = &node.nodes; } } + using std::swap; + swap(cats_, cats); + swap(nodes_, nodes); + level_ = level; } -spark::LogHandler::~LogHandler() { +spark::detail::LogFilter::~LogFilter() { } -LogLevel spark::LogHandler::categoryLevel(const char *category) const { - if (!category || filters_.empty()) { - return level_; // Default level - } - LogLevel level = level_; - const std::vector *filters = &filters_; // Root nodes - size_t pos = 0; - for (size_t i = 0;; ++i) { - if (category[i] && category[i] != '.') { // Category name separator - continue; - } - const size_t size = i - pos; - if (!size) { - break; // Invalid category name - } - const char* const name = category + pos; - // Use binary search to find node for current subcategory - bool found = false; - auto it = std::lower_bound(filters->begin(), filters->end(), std::make_pair(name, size), - [&found](const FilterData &filter, const std::pair &value) { - const int cmp = std::strncmp(filter.name, value.first, std::min(filter.size, value.second)); - if (cmp == 0) { - if (filter.size == value.second) { - found = true; - } - return filter.size < value.second; +LogLevel spark::detail::LogFilter::level(const char *category) const { + LogLevel level = level_; // Default level + if (!nodes_.isEmpty() && category) { + const Vector *pNodes = &nodes_; // Root nodes + const char *name = nullptr; // Subcategory name + size_t size = 0; // Name length + while ((name = nextSubcategoryName(category, size))) { + bool found = false; + const int index = nodeIndex(*pNodes, name, size, found); + if (!found) { + break; } - return cmp < 0; - }); - if (!found) { - break; - } - if (it->level >= 0) { - level = (LogLevel)it->level; - } - if (!category[i]) { - break; + const Node &node = pNodes->at(index); + if (node.level >= 0) { + level = (LogLevel)node.level; + } + pNodes = &node.nodes; } - filters = &it->filters; - pos = i + 1; } return level; } +int spark::detail::LogFilter::nodeIndex(const Vector &nodes, const char *name, size_t size, bool &found) { + // Using binary search to find existent node or suitable position for new node + return std::distance(nodes.begin(), std::lower_bound(nodes.begin(), nodes.end(), std::make_pair(name, size), + [&found](const Node &node, const std::pair &value) { + const int cmp = strncmp(node.name, value.first, std::min(node.size, value.second)); + if (cmp == 0) { + if (node.size == value.second) { // Lengths are equal + found = true; // Allows caller code to avoid extra call to strncmp() + return false; + } + return node.size < value.second; + } + return cmp < 0; + })); +} + // spark::StreamLogHandler void spark::StreamLogHandler::logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) { - char buf[16]; + const char *s = nullptr; // Timestamp if (attr.has_time) { - snprintf(buf, sizeof(buf), "%010u ", (unsigned)attr.time); - write(buf); + printf("%010u ", (unsigned)attr.time); } // Category if (category) { - write("["); + write('['); write(category); - write("] "); + write("] ", 2); } // Source file if (attr.has_file) { - // Strip directory path - const char *s = extractFileName(attr.file); + s = extractFileName(attr.file); // Strip directory path write(s); // File name if (attr.has_line) { - write(":"); - snprintf(buf, sizeof(buf), "%d", attr.line); // Line number - write(buf); + write(':'); + printf("%d", (int)attr.line); // Line number } if (attr.has_function) { - write(", "); + write(", ", 2); } else { - write(": "); + write(": ", 2); } } // Function name if (attr.has_function) { - // Strip argument and return types for better readability size_t n = 0; - const char *s = extractFuncName(attr.function, &n); + s = extractFuncName(attr.function, &n); // Strip argument and return types write(s, n); - write("(): "); + write("(): ", 4); } // Level - write(levelName(level)); - write(": "); + s = levelName(level); + write(s); + write(": ", 2); // Message if (msg) { write(msg); } // Additional attributes if (attr.has_code || attr.has_details) { - write(" ["); + write(" [", 2); + // Code if (attr.has_code) { - write("code"); - write(" = "); - snprintf(buf, sizeof(buf), "%" PRIiPTR, attr.code); - write(buf); + write("code = ", 7); + printf("%" PRIiPTR, (intptr_t)attr.code); } + // Details if (attr.has_details) { if (attr.has_code) { - write(", "); + write(", ", 2); } - write("details"); - write(" = "); + write("details = ", 10); write(attr.details); } - write("]"); + write(']'); + } + write("\r\n", 2); +} + +// spark::JSONStreamLogHandler +void spark::JSONStreamLogHandler::logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) { + JSONStreamWriter json(*this->stream()); + json.beginObject(); + // Level + const char *s = levelName(level); + json.name("l", 1).value(s); + // Message + if (msg) { + json.name("m", 1).value(msg); + } + // Category + if (category) { + json.name("c", 1).value(category); + } + // File name + if (attr.has_file) { + s = extractFileName(attr.file); // Strip directory path + json.name("f", 1).value(s); + } + // Line number + if (attr.has_line) { + json.name("ln", 2).value(attr.line); + } + // Function name + if (attr.has_function) { + size_t n = 0; + s = extractFuncName(attr.function, &n); // Strip argument and return types + json.name("fn", 2).value(s, n); + } + // Timestamp + if (attr.has_time) { + json.name("t", 1).value((unsigned)attr.time); + } + // Code (additional attribute) + if (attr.has_code) { + json.name("code", 4).value((int)attr.code); + } + // Details (additional attribute) + if (attr.has_details) { + json.name("detail", 6).value(attr.details); + } + json.endObject(); + this->stream()->write((const uint8_t*)"\r\n", 2); +} + +#if Wiring_LogConfig + +// spark::DefaultLogHandlerFactory +LogHandler* spark::DefaultLogHandlerFactory::createHandler(const char *type, LogLevel level, LogCategoryFilters filters, + Print *stream, const JSONValue ¶ms) { + if (strcmp(type, "JSONStreamLogHandler") == 0) { + if (!stream) { + return nullptr; // Output stream is not specified + } + return new(std::nothrow) JSONStreamLogHandler(*stream, level, std::move(filters)); + } else if (strcmp(type, "StreamLogHandler") == 0) { + if (!stream) { + return nullptr; + } + return new(std::nothrow) StreamLogHandler(*stream, level, std::move(filters)); + } + return nullptr; // Unknown handler type +} + +spark::DefaultLogHandlerFactory* spark::DefaultLogHandlerFactory::instance() { + static DefaultLogHandlerFactory factory; + return &factory; +} + +// spark::DefaultOutputStreamFactory +Print* spark::DefaultOutputStreamFactory::createStream(const char *type, const JSONValue ¶ms) { +#if PLATFORM_ID != 3 + if (strcmp(type, "Serial") == 0) { + Serial.begin(); + return &Serial; + } +#if Wiring_USBSerial1 + if (strcmp(type, "USBSerial1") == 0) { + USBSerial1.begin(); + return &USBSerial1; + } +#endif + if (strcmp(type, "Serial1") == 0) { + int baud = 9600; + getParams(params, &baud); + Serial1.begin(baud); + return &Serial1; + } +#endif // PLATFORM_ID != 3 + return nullptr; +} + +void spark::DefaultOutputStreamFactory::destroyStream(Print *stream) { +#if PLATFORM_ID != 3 + if (stream == &Serial) { + // Uninitializing primary USB serial causes the device to get disconnected from the host + // Serial.end(); + return; + } +#if Wiring_USBSerial1 + if (stream == &USBSerial1) { + USBSerial1.end(); + return; + } +#endif + if (stream == &Serial1) { + Serial1.end(); + return; + } +#endif // PLATFORM_ID != 3 + OutputStreamFactory::destroyStream(stream); +} + +spark::DefaultOutputStreamFactory* spark::DefaultOutputStreamFactory::instance() { + static DefaultOutputStreamFactory factory; + return &factory; +} + +void spark::DefaultOutputStreamFactory::getParams(const JSONValue ¶ms, int *baudRate) { + JSONObjectIterator it(params); + while (it.next()) { + if (it.name() == "baud" && baudRate) { + *baudRate = it.value().toInt(); + } } - write("\r\n"); } // spark::LogManager -void spark::LogManager::addHandler(LogHandler *handler) { - const auto it = std::find(handlers_.cbegin(), handlers_.cend(), handler); - if (it == handlers_.end()) { - handlers_.push_back(handler); - if (handlers_.size() == 1) { - log_set_callbacks(logMessage, logWrite, logEnabled, nullptr); // Set system callbacks +struct spark::LogManager::FactoryHandler { + String id; + LogHandler *handler; + Print *stream; +}; + +#endif // Wiring_LogConfig + +spark::LogManager::LogManager() { +#if Wiring_LogConfig + handlerFactory_ = DefaultLogHandlerFactory::instance(); + streamFactory_ = DefaultOutputStreamFactory::instance(); +#endif +} + +spark::LogManager::~LogManager() { + resetSystemCallbacks(); +#if Wiring_LogConfig + WITH_LOCK(mutex_) { + destroyFactoryHandlers(); + } +#endif +} + +bool spark::LogManager::addHandler(LogHandler *handler) { + WITH_LOCK(mutex_) { + if (activeHandlers_.contains(handler) || !activeHandlers_.append(handler)) { + return false; + } + if (activeHandlers_.size() == 1) { + setSystemCallbacks(); } } + return true; } void spark::LogManager::removeHandler(LogHandler *handler) { - const auto it = std::find(handlers_.begin(), handlers_.end(), handler); - if (it != handlers_.end()) { - if (handlers_.size() == 1) { - log_set_callbacks(nullptr, nullptr, nullptr, nullptr); // Reset system callbacks + WITH_LOCK(mutex_) { + if (activeHandlers_.removeOne(handler) && activeHandlers_.isEmpty()) { + resetSystemCallbacks(); } - handlers_.erase(it); } } @@ -266,28 +691,167 @@ spark::LogManager* spark::LogManager::instance() { return &mgr; } +#if Wiring_LogConfig + +bool spark::LogManager::addFactoryHandler(const char *id, const char *handlerType, LogLevel level, LogCategoryFilters filters, + const JSONValue &handlerParams, const char *streamType, const JSONValue &streamParams) { + WITH_LOCK(mutex_) { + destroyFactoryHandler(id); // Destroy existent handler with the same ID + FactoryHandler h; + h.id = id; + if (!h.id.length()) { + return false; // Empty handler ID or memory allocation error + } + // Create output stream (optional) + std::unique_ptr stream(nullptr, streamFactory_); + if (streamType) { + if (streamFactory_) { + stream.reset(streamFactory_->createStream(streamType, streamParams)); + } + if (!stream) { + return false; // Unsupported stream type + } + } + // Create log handler + std::unique_ptr handler(nullptr, handlerFactory_); + if (handlerType && handlerFactory_) { + handler.reset(handlerFactory_->createHandler(handlerType, level, std::move(filters), stream.get(), handlerParams)); + } + if (!handler) { + return false; // Unsupported handler type + } + h.handler = handler.get(); + h.stream = stream.get(); + if (!factoryHandlers_.append(std::move(h))) { + return false; + } + if (!activeHandlers_.append(h.handler)) { + factoryHandlers_.takeLast(); // Revert factoryHandlers_.append() + return false; + } + if (activeHandlers_.size() == 1) { + setSystemCallbacks(); + } + handler.release(); // Release scope guard pointers + stream.release(); + } + return true; +} + +void spark::LogManager::removeFactoryHandler(const char *id) { + WITH_LOCK(mutex_) { + destroyFactoryHandler(id); + } +} + +void spark::LogManager::enumFactoryHandlers(void(*callback)(const char *id, void *data), void *data) { + WITH_LOCK(mutex_) { + for (const FactoryHandler &h: factoryHandlers_) { + callback(h.id.c_str(), data); + } + } +} + +void spark::LogManager::setHandlerFactory(LogHandlerFactory *factory) { + WITH_LOCK(mutex_) { + if (handlerFactory_ != factory) { + destroyFactoryHandlers(); + handlerFactory_ = factory; + } + } +} + +void spark::LogManager::setStreamFactory(OutputStreamFactory *factory) { + WITH_LOCK(mutex_) { + if (streamFactory_ != factory) { + destroyFactoryHandlers(); + streamFactory_ = factory; + } + } +} + +void spark::LogManager::destroyFactoryHandler(const char *id) { + for (int i = 0; i < factoryHandlers_.size(); ++i) { + const FactoryHandler &h = factoryHandlers_.at(i); + if (h.id == id) { + activeHandlers_.removeOne(h.handler); + if (activeHandlers_.isEmpty()) { + resetSystemCallbacks(); + } + handlerFactory_->destroyHandler(h.handler); + if (h.stream) { + streamFactory_->destroyStream(h.stream); + } + factoryHandlers_.removeAt(i); + break; + } + } +} + +void spark::LogManager::destroyFactoryHandlers() { + for (const FactoryHandler &h: factoryHandlers_) { + activeHandlers_.removeOne(h.handler); + if (activeHandlers_.isEmpty()) { + resetSystemCallbacks(); + } + handlerFactory_->destroyHandler(h.handler); + if (h.stream) { + streamFactory_->destroyStream(h.stream); + } + } + factoryHandlers_.clear(); +} + +#endif // Wiring_LogConfig + +void spark::LogManager::setSystemCallbacks() { + log_set_callbacks(logMessage, logWrite, logEnabled, nullptr); +} + +void spark::LogManager::resetSystemCallbacks() { + log_set_callbacks(nullptr, nullptr, nullptr, nullptr); +} + void spark::LogManager::logMessage(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved) { - const auto &handlers = instance()->handlers_; - for (size_t i = 0; i < handlers.size(); ++i) { - handlers[i]->message(msg, (LogLevel)level, category, *attr); + LogManager *that = instance(); + WITH_LOCK(that->mutex_) { + for (LogHandler *handler: that->activeHandlers_) { + handler->message(msg, (LogLevel)level, category, *attr); + } } } void spark::LogManager::logWrite(const char *data, size_t size, int level, const char *category, void *reserved) { - const auto &handlers = instance()->handlers_; - for (size_t i = 0; i < handlers.size(); ++i) { - handlers[i]->write(data, size, (LogLevel)level, category); + LogManager *that = instance(); + WITH_LOCK(that->mutex_) { + for (LogHandler *handler: that->activeHandlers_) { + handler->write(data, size, (LogLevel)level, category); + } } } int spark::LogManager::logEnabled(int level, const char *category, void *reserved) { + LogManager *that = instance(); int minLevel = LOG_LEVEL_NONE; - const auto &handlers = instance()->handlers_; - for (size_t i = 0; i < handlers.size(); ++i) { - const int level = handlers[i]->categoryLevel(category); - if (level < minLevel) { - minLevel = level; + WITH_LOCK(that->mutex_) { + for (LogHandler *handler: that->activeHandlers_) { + const int level = handler->level(category); + if (level < minLevel) { + minLevel = level; + } } } return (level >= minLevel); } + +#if Wiring_LogConfig + +// spark:: +bool spark::logProcessConfigRequest(char *buf, size_t bufSize, size_t reqSize, size_t *repSize, DataFormat fmt) { + if (fmt == DATA_FORMAT_JSON) { + return JSONRequestHandler::process(buf, bufSize, reqSize, repSize); + } + return false; // Unsupported request format +} + +#endif // Wiring_LogConfig diff --git a/wiring/src/user.cpp b/wiring/src/user.cpp index b0be2b7747..a16ac6695c 100644 --- a/wiring/src/user.cpp +++ b/wiring/src/user.cpp @@ -28,6 +28,7 @@ #include "spark_wiring_usbserial.h" #include "spark_wiring_usartserial.h" #include "spark_wiring_watchdog.h" +#include "spark_wiring_logging.h" #include "rng_hal.h" @@ -162,6 +163,37 @@ bool __backup_ram_was_valid() { return false; } #endif +#include "system_control.h" + +#ifdef USB_VENDOR_REQUEST_ENABLE + +// Synchronous handler for customizable requests (USBRequestType::USB_REQUEST_CUSTOM) +bool __attribute((weak)) usb_request_custom_handler(char* buf, size_t buf_size, size_t req_size, size_t* rep_size) { + return false; +} + +bool usb_request_app_handler(USBRequest* req, void* reserved) { + switch (req->type) { + case USB_REQUEST_LOG_CONFIG: { + if (!spark::logProcessConfigRequest(req->data, USB_REQUEST_BUFFER_SIZE, req->request_size, &req->reply_size, (DataFormat)req->format)) { + return false; + } + system_set_usb_request_result(req, USB_REQUEST_RESULT_OK, nullptr); + return true; + } + case USB_REQUEST_CUSTOM: { + if (!usb_request_custom_handler(req->data, USB_REQUEST_BUFFER_SIZE, req->request_size, &req->reply_size)) { + return false; + } + system_set_usb_request_result(req, USB_REQUEST_RESULT_OK, nullptr); + return true; + } + default: + return false; // Unsupported request type + } +} + +#endif // USB_VENDOR_REQUEST_ENABLE void module_user_init_hook() { @@ -183,4 +215,8 @@ void module_user_init_hook() random_seed_from_cloud(seed); } #endif + +#ifdef USB_VENDOR_REQUEST_ENABLE + system_set_usb_request_app_handler(usb_request_app_handler, nullptr); +#endif }