Runtime logging configuration by sergeuz · Pull Request #1748 · particle-iot/device-os

sergeuz · 2019-04-12T14:33:44Z

Changelog

Use protobuf to encode logging configuration requests.
Rename FEATURE_CONFIGURABLE_LOGGING to FEATURE_LOG_CONFIG.
Disable logging to Serial in listening mode.
Initialize user module in monolithic builds on Gen 3 (backup RAM, RNG, etc.)

Problem

This PR reimplements the control requests for runtime logging configuration using protobuf (the original implementation used JSON).

The most part of the logging framework is implemented in the user module. In order to reduce the overhead for user applications, parsing of protobuf messages is performed in the system module. A deserialized configuration is then passed to the user module via a thin system API layer (see system_logging.h).

Note that the capability to configure logging at runtime is disabled by default. The application needs to set a feature flag in order to enable it (FEATURE_LOG_CONFIG). Unfortunately, we can't enable this feature by default and provide an option to disable it, because in that case the linker won't be able to optimize the unused code out. A solution would be to move the logging framework to the system module entirely.

Steps to Test

Flash the following application to a device:

#include "application.h"

STARTUP(System.enableFeature(FEATURE_LOG_CONFIG))

void setup() {
}

void loop() {
    delay(3000);

    Log.trace("This is a trace message");
    Log.info("This is an info message");
    Log.warn("This is a warning message");
    Log.error("This is an error message");
}

Clone and build the particle-usb library:

git clone https://github.com/particle-iot/particle-usb.git
cd particle-usb
npm install

Create a directory for the test Node application and paste the following code to test.js:

#!/usr/bin/env node
const { getDevices } = require('particle-usb');

async function openDevice() {
  const devs = await getDevices();
  if (devs.length == 0) {
    throw new Error('No devices found');
  }
  const dev = devs[0];
  await dev.open();
  return dev;
}

async function add() {
  const dev = await openDevice();
  // Enable logging on the Serial interface
  await dev.addLogHandler({
    id: 'logger_1',
    stream: 'Serial'
  });
  // Enable logging on the Serial1 interface
  await dev.addLogHandler({
    id: 'logger_2',
    format: 'json',
    stream: 'Serial1',
    baudRate: 115200
  });
}

async function remove() {
  const dev = await openDevice();
  await dev.removeLogHandler({ id: 'logger_1' });
  await dev.removeLogHandler({ id: 'logger_2' });
}

async function list() {
  const dev = await openDevice();
  const handlers = await dev.getLogHandlers();
  console.dir(handlers);
}

async function run(cmd) {
  try {
    switch (cmd) {
      case 'add':
        await add();
        break;
      case 'remove':
        await remove();
        break;
      case 'list':
        await list();
        break;
      default:
        throw new Error('Unknown command');
    }
  } catch (e) {
    console.log(`Error: ${e.message}`);
  }
}

run(process.argv[2]);

Install particle-usb:

npm install file:path/to/particle-usb

Run ./test.js add and verify that you can see the device's logging output on the Serial and Serial1 interfaces:

$ screen /dev/ttyACM0
000944683 [app] TRACE: This is a trace message
0000944684 [app] INFO: This is an info message
0000944684 [app] WARN: This is a warning message
0000944691 [app] ERROR: This is an error message

$ screen /dev/ttyUSB0 115200
{"l":"t","m":"This is a trace message","c":"app","t":12926}
{"l":"i","m":"This is an info message","c":"app","t":12926}
{"l":"w","m":"This is a warning message","c":"app","t":12927}
{"l":"e","m":"This is an error message","c":"app","t":12938}

Run ./test.js list and verify that the command shows logger_1 and logger_2 in the list of active log handlers.
Run ./test.js remove and verify that the device has stopped to generate log messages.
Run ./test.js list and verify that the list of active log handlers is empty.

References

m-mcgowan · 2019-05-30T23:46:51Z

+
+namespace control {
+
+namespace diagnostics {


The diagnostics namespace seems a little strange..can you add a comment about the reasoning behind the naming?

m-mcgowan · 2019-05-31T00:05:57Z

-        return SYSTEM_ERROR_NOT_SUPPORTED;
-    }
+int log_config(int command, const void* command_data, void* command_result) {
+    CHECK_TRUE(g_logConfigCallback, SYSTEM_ERROR_NOT_SUPPORTED);


Nice! 👍 I'd love something like this to be included in the CHECK macro docs so that we can help educate that this is useful for parameter or state validation, with the benefit of logging/checkpoints etc.

m-mcgowan · 2019-05-31T00:09:27Z

+    const DecodedCString idStr(&pbReq.id);
+    Filters f;
+    pbReq.filters.arg = &f;
+    pbReq.filters.funcs.decode = [](pb_istream_t* strm, const pb_field_t* field, void** arg) {


A link to the documentation for the mechanism used by protobuf here to do the decoding would be helpful. This stuff is pretty cryptic if you are not working closely with it.

m-mcgowan · 2019-05-31T00:13:49Z

+    Filters f;
+    pbReq.filters.arg = &f;
+    pbReq.filters.funcs.decode = [](pb_istream_t* strm, const pb_field_t* field, void** arg) {
+        const auto f = (Filters*)*arg;


Would it be clearer to make this a reference so that we are immediately aware it's not a pointer to an array of filters?

m-mcgowan · 2019-05-31T19:51:13Z

+    uint16_t filter_count; ///< Number of category filters.
+    uint8_t type; ///< Handler type (a value defined by the `log_handler_type` enum).
+    uint8_t level; ///< Default logging level (a value defined by the `LogLevel` enum).
+} __attribute__((aligned(4))) log_handler;


Bravo. If the struct has to adhere to a very specific layout for external compliance, it might be a good idea to add some static macros asserting the layout is as expected.

There's no requirement for specific alignment. This API uses C-style inheritance and aligning base structures to a 4-byte boundary helps to define predictable layout in derived structures

m-mcgowan · 2019-05-31T20:36:29Z

-    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);
+    virtual LogHandler* createHandler(log_handler_type type, LogLevel level, LogCategoryFilters filters, Print* stream = nullptr) = 0;


This looks like an API change - can you clarify please how this is a safe change and doesn't break compatibility. I believe I know why, but don't want to presume!

It's technically a breaking change, however, the API was marked as experimental in the code and was never documented: spark_wiring_logging.h#L449 (develop)

m-mcgowan · 2019-05-31T20:47:59Z

+    r->level = (LogLevel)cmd->handler->level;
+    if (cmd->stream) {
+        r->streamType = (log_stream_type)cmd->stream->type;
+        if (isSerialStreamType(r->streamType)) {


Should determination of serial streams be moved down to the main API? Seems like it should live closer to the stream type definitions.

m-mcgowan · 2019-05-31T20:53:05Z

+        const auto r = (Result*)data;
+        Handler h = {};
+        h.handlerId = id;
+        if (!h.handlerId) {


CHECK_TRUE macro?

CHECK_TRUE() returns an error code while this callback is expected to return bool

m-mcgowan · 2019-05-31T21:15:55Z

 #if PLATFORM_ID != 3
    if (stream == &Serial) {
-        Serial.end();
+        // FIXME: Uninitializing the primary USB serial detaches a Gen 3 device from the host


Given it's a Gen3 issue, should we make it platform conditional?

…erent error code to notify the client that the logging feature is disabled

sergeuz added enhancement needs review labels Apr 12, 2019

sergeuz mentioned this pull request Apr 12, 2019

Logging configuration API particle-iot/particle-usb#10

Merged

sergeuz requested a review from m-mcgowan April 12, 2019 17:36

sergeuz mentioned this pull request Apr 16, 2019

Runtime Device OS logging configuration particle-iot/particle-cli#481

Closed

sergeuz force-pushed the feature/log_config branch from 1d8cca4 to 8d12d4b Compare May 20, 2019 21:37

monkbroc reviewed May 24, 2019

View reviewed changes

Comment thread wiring/src/spark_wiring_logging.cpp Outdated

sergeuz force-pushed the feature/log_config branch from 1259cae to 36fb798 Compare May 28, 2019 00:36

m-mcgowan approved these changes May 31, 2019

View reviewed changes

sergeuz added 21 commits June 25, 2019 17:03

Define new requests to configure the logging

c3e9793

Initial system logging API

92c4837

Implement handlers for logging configuration requests

4beb937

Use the system API to configure the logging

42992c5

Implement the LOG_CONFIG_GET_HANDLERS command

1507f0e

Fix callback registration

68b99dd

Do not close the primary USB serial when unregistering a log handler

ca76554

Refactoring

d07d8d4

Use shorter log level names when formatting a log message as JSON

859d326

[Gen 3] Invoke the user module hook in monolithic builds

be75a25

Disable unit tests for logging configuration; minor fixes

9779d4b

Minor renamings

7ee4471

Rename FEATURE_CONFIGURABLE_LOGGING to FEATURE_LOG_CONFIG; use a diff…

957e252

…erent error code to notify the client that the logging feature is disabled

Do not mix logging and serial console output

cae58bc

Fix rebase artifacts

0fa9a48

Fix unit tests

0954627

Minor bugfix

dd09b47

Initialize log handlers asynchronously; refactoring

ddd3535

Disable obsolete and unused WiFi and network configuration requests

712673f

Bugfixes

59307aa

Restore the echo request

c2c0657

Minor fixes

2a2b8e0

sergeuz force-pushed the feature/log_config branch from a654b5d to 2a2b8e0 Compare June 25, 2019 15:03

technobly added the in progress label Jul 2, 2019

sergeuz mentioned this pull request Sep 9, 2019

Do not mix logging and serial console output #1909

Merged

avtolstoy force-pushed the develop branch from c253104 to 55f59c1 Compare June 3, 2020 19:02

avtolstoy force-pushed the develop branch from 77b2534 to 5c09a50 Compare December 9, 2020 22:05

Uh oh!

Conversation

sergeuz commented Apr 12, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Changelog

Problem

Steps to Test

References

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

sergeuz commented Apr 12, 2019 •

edited

Loading