Runtime logging configuration #1127

sergeuz · 2016-09-23T23:02:59Z

This PR adds support for runtime logging configuration, which allows to enable logging on already running system via USB control requests. Some background on the topic can be found here: #1037. Note that this PR is based on the common code from another branch which is being reviewed here: #1126

Parameters that can be configured dynamically: destination stream (Serial, Serial1, USBSerial1), message format (plain text, JSON), message filtering (level and category-based).

This PR also adds basic tools for acceptance testing, such as handling of serial IO, USB requests, application flashing, etc. The test utilizing above functionality can be found here.

I'll be adding further comments directly in the code to provide more details on the implementation.

Doneness:

Contributor has signed CLA
Problem and Solution clearly stated
Code peer reviewed
API tests compiled
Run unit/integration/application tests on device
Add documentation
Add to CHANGELOG.md after merging (add links to docs and issues)

Features

Added support for runtime logging configuration, which allows to enable logging on already running system via USB control requests.

sergeuz · 2016-09-23T23:25:10Z

services/src/logging.cpp

@@ -78,20 +78,21 @@ 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;


Current application callback is copied to a local variable, because LogManager may reset it at any time in multithreaded configuration (turning low-level logging functions to no-op), e.g. when last log handler has been unregistered.

sergeuz · 2016-09-23T23:38:29Z

system/inc/active_object.h

+    Task* availTask_; // Task pool
+    Task* firstTask_; // Task queue
+    Task* lastTask_;
+};


This class implements a simple callback queue where callbacks can be enqueued from an ISR and then invoked asynchronously by a regular thread. The implementation doesn't use os_queue_t and can be used on platforms without concurrency support. Currently, there's a single queue for ISR tasks, and it's processed by the system thread as part of the primary event loop.

sergeuz · 2016-09-24T00:35:59Z

system/inc/system_control.h

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


This structure describes an asynchronous USB request. A request handler processes request data using data and request_size fields, then optionally stores reply data to the same buffer, sets reply_size field accordingly and calls system_set_usb_request_result() function to finalize processing.

sergeuz · 2016-09-24T00:39:11Z

system/inc/system_control.h

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


This function allows to set a callback that will be invoked for requests that should be processed in application thread. In current implementation such requests are USB_REQUEST_LOG_CONFIG and USB_REQUEST_CUSTOM.

sergeuz · 2016-09-24T00:43:22Z

system/inc/system_control.h

+    ~USBRequestData();
+  };
+
+  USBRequestData usbReq_;


Only one active asynchronous USB request at a time is supported.

sergeuz · 2016-09-24T01:23:19Z

wiring/inc/spark_wiring_logging.h

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


This class implements JSON-formatted output for log messages to simplify machine processing.

sergeuz · 2016-09-24T01:29:41Z

wiring/inc/spark_wiring_logging.h

+    virtual LogHandler* createHandler(const char *type, LogLevel level, LogCategoryFilters filters, Print *stream,
+            const JSONValue &params) = 0; // TODO: Use some generic container or a buffer instead of JSONValue
+    virtual void destroyHandler(LogHandler *handler);
+};


Handler and stream factory classes are extension points of the logging framework and allow to dynamically configure custom log handlers in the same way as built-in ones. This feature is also used for unit testing.

sergeuz · 2016-09-24T01:31:59Z

wiring/src/spark_wiring_logging.cpp

+};
+
+typedef FactoryDeleter<LogHandler, LogHandlerFactory, &LogHandlerFactory::destroyHandler> LogHandlerFactoryDeleter;
+typedef FactoryDeleter<Print, OutputStreamFactory, &OutputStreamFactory::destroyStream> OutputStreamFactoryDeleter;


These custom deleters are used with std::unique_ptr to simplify error handling.

sergeuz · 2016-09-24T01:36:20Z

wiring/src/spark_wiring_logging.cpp

-            }
-            const char* const name = category + pos;
-            // Use binary search to find existent node or position for new node
+}


This code has been refactored to reduce code duplication.

sergeuz · 2016-09-24T01:38:26Z

wiring/src/spark_wiring_logging.cpp

+#if PLATFORM_ID != 3
+    if (stream == &Serial) {
+        // Uninitializing primary USB serial causes the device to get disconnected from the host
+        // Serial.end();


Fixed by this PR: #1122

avtolstoy · 2016-10-16T14:06:43Z

user/tests/accept/init_env

+      ;;
+    electron)
+      USB_VENDOR_ID=2b04
+      USB_PRODUCT_ID=d00a


This should be c00a (otherwise it targets Electron in DFU mode)

Thanks! Honestly, I don't remember from where I copied these IDs. Since you're working with this branch already, would you mind committing correct IDs?

avtolstoy · 2016-10-16T14:06:59Z

user/tests/accept/init_env

+      ;;
+    p1)
+      USB_VENDOR_ID=2b04
+      USB_PRODUCT_ID=d008


This should be c008 (otherwise it targets P1 in DFU mode)

…s for acceptance testing

…n order for unit tests to pass

…ed wLength = 0

technobly

💥

user/tests/accept/init_env:41 and 45 should be c00_ (fixed in Acceptance tests for PR #1097 (OTA/YModem update result) #1153)
wiring/src/spark_wiring_logging.cpp:623 can be uncommented after PR 1122 is merged

sergeuz mentioned this pull request Sep 24, 2016

Common tools for the Wiring library and unit testing #1126

Merged

7 tasks

sergeuz commented Sep 24, 2016

View reviewed changes

sergeuz force-pushed the feature/usb_logging_2_of_2 branch from fe2ad9f to 1e04ef7 Compare September 29, 2016 19:47

sergeuz added this to the 0.7.x milestone Oct 8, 2016

avtolstoy reviewed Oct 16, 2016

View reviewed changes

sergeuz force-pushed the feature/usb_logging_1_of_2 branch 2 times, most recently from 0397166 to b1d7d74 Compare October 22, 2016 00:38

sergeuz force-pushed the feature/usb_logging_2_of_2 branch from 1e04ef7 to 6bf20b5 Compare October 22, 2016 00:48

sergeuz force-pushed the feature/usb_logging_1_of_2 branch from b1d7d74 to 7d404a8 Compare October 29, 2016 20:01

Runtime logging configuration; asynchronous USB requests; helper tool…

cbda226

…s for acceptance testing

sergeuz force-pushed the feature/usb_logging_2_of_2 branch from 6bf20b5 to cbda226 Compare October 29, 2016 20:24

avtolstoy added 3 commits October 30, 2016 04:49

Allow logging from an ISR when DEBUG_BUILD=y

d81371e

Do not use ATOMIC_BLOCK() in spark_wiring_logging.cpp on PLATFORM=3 i…

be9c07a

…n order for unit tests to pass

usb_hal: Initiate data stage anyway, if vendor request handler return…

6bb3318

…ed wLength = 0

avtolstoy mentioned this pull request Oct 30, 2016

Acceptance tests for PR #1097 (OTA/YModem update result) #1153

Merged

7 tasks

technobly self-assigned this Nov 21, 2016

technobly approved these changes Nov 22, 2016

View reviewed changes

technobly merged commit f835972 into feature/usb_logging_1_of_2 Nov 22, 2016

technobly deleted the feature/usb_logging_2_of_2 branch November 22, 2016 04:23

technobly removed their assignment Nov 29, 2016

avtolstoy mentioned this pull request Nov 29, 2016

USB Serial might deadlock when interrupts are masked #1186

Merged

7 tasks

technobly modified the milestones: 0.7.x, 0.6.1 Nov 29, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Runtime logging configuration #1127

Runtime logging configuration #1127

sergeuz commented Sep 23, 2016 •

edited by technobly

Loading

sergeuz Sep 23, 2016 •

edited

Loading

sergeuz Sep 23, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

avtolstoy Oct 16, 2016 •

edited

Loading

sergeuz Oct 16, 2016

avtolstoy Oct 16, 2016

technobly left a comment •

edited by avtolstoy

Loading

Runtime logging configuration #1127

Runtime logging configuration #1127

Conversation

sergeuz commented Sep 23, 2016 • edited by technobly Loading

Features

sergeuz Sep 23, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 23, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Sep 24, 2016 • edited Loading

Choose a reason for hiding this comment

avtolstoy Oct 16, 2016 • edited Loading

Choose a reason for hiding this comment

sergeuz Oct 16, 2016

Choose a reason for hiding this comment

avtolstoy Oct 16, 2016

Choose a reason for hiding this comment

technobly left a comment • edited by avtolstoy Loading

Choose a reason for hiding this comment

sergeuz commented Sep 23, 2016 •

edited by technobly

Loading

sergeuz Sep 23, 2016 •

edited

Loading

sergeuz Sep 23, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

sergeuz Sep 24, 2016 •

edited

Loading

avtolstoy Oct 16, 2016 •

edited

Loading

technobly left a comment •

edited by avtolstoy

Loading