Runtime logging configuration

[sergeuz]

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

1. 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");
}

2. Clone and build the particle-usb library:

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

3. 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]);

4. Install particle-usb:

npm install file:path/to/particle-usb

5. 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}

6. Run ./test.js list and verify that the command shows logger_1 and logger_2 in the list of active log handlers.

7. Run ./test.js remove and verify that the device has stopped to generate log messages.

8. Run ./test.js list and verify that the list of active log handlers is empty.

References

• particle-usb/#10
• particle-cli/#481
• [ch31052]

[m-mcgowan]

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

[m-mcgowan]

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]

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]

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]

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.

[sergeuz]

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]

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!

[sergeuz]

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]

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]

CHECK_TRUE macro?

[sergeuz]

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

[m-mcgowan]

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

[sergeuz]

👍