Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Additional attributes for log messages #1026

Merged
merged 19 commits into from
Jun 15, 2016
Merged
Show file tree
Hide file tree
Changes from 17 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion communication/tests/catch/hal_stubs.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

#include <stdint.h>
#include <stdlib.h>
#include "logging.h"

extern "C" uint32_t HAL_RNG_GetRandomNumber()
{
Expand All @@ -31,7 +32,7 @@ extern "C" uint32_t HAL_Core_Compute_CRC32(const uint8_t* buf, size_t length)
return 0;
}

extern "C" void log_message(int level, const char *category, const char *file, int line, const char *func, void *reserved, const char *fmt, ...)
extern "C" void log_message(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, ...)
{
}

Expand Down
69 changes: 59 additions & 10 deletions docs/reference/firmware.md
Original file line number Diff line number Diff line change
Expand Up @@ -8469,7 +8469,7 @@ At higher level, the logging framework consists of two parts represented by thei

The library provides default logger instance named `Log`, which can be used for all typical logging operations. Note that applications still need to instantiate at least one log handler in order to enable logging, otherwise most of the logging operations will have no effect. In the provided example, the application uses `SerialLogHandler` which sends the logging output to the primary serial over USB interface.

Consider the following output generated by the example application:
Consider the following logging output as generated by the example application:

`0000000047 [app] INFO: This is info message`
`0000000050 [app] WARN: This is warning message`
Expand Down Expand Up @@ -8525,7 +8525,7 @@ void loop() {
}
```

Below is the logging output generated by the example application, where the trace and info messages have been filtered out according to the log handler settings:
In the provided example, the trace and info messages will be filtered out according to the log handler settings, which prevent log messages below the `LOG_LEVEL_WARN` level from being logged:

`0000000050 [app] WARN: This is warning message`
`0000000100 [app] ERROR: This is error message`
Expand Down Expand Up @@ -8554,7 +8554,7 @@ void connect() {
log.trace("Connecting to server"); // Using local logger
}

Serial1LogHandler logHandler(LOG_LEVEL_WARN, { // Logging level for non-application messages
SerialLogHandler logHandler(LOG_LEVEL_WARN, { // Logging level for non-application messages
{ "app", LOG_LEVEL_INFO }, // Default logging level for all application messages
{ "app.network", LOG_LEVEL_TRACE } // Logging level for networking messages
});
Expand All @@ -8571,20 +8571,56 @@ void loop() {

Category names are written in all lower case and may contain arbitrary number of _subcategories_ separated by period character. In order to not interfere with the system logging, it is recommended to always add `app` prefix to all application-specific category names.

Below is the logging output generated by the example application:
The example application generates the following logging output:

`0000000044 [app] INFO: System started`
`0000000044 [app.network] TRACE: Connecting to server`

Note that the trace message containing device ID has been filtered out due to the log handler settings, which instruct the handler to log a message with the `app` category only if its logging level is at or above the `LOG_LEVEL_INFO` level.
Note that the trace message containing device ID has been filtered out according to the log handler settings, which prevent log messages with the `app` category from being logged if their logging level is below the `LOG_LEVEL_INFO` level.

Category filters are specified using _initializer list_ syntax with each element of the list containing a filter string and a minimum logging level required for messages with matching category to be logged. Note that filter string matches not only exact category name but any of its subcategory names as well, for example:

* `a` – matches `a`, `a.b`, `a.b.c` but not `aaa` or `aaa.b`
* `b.c` – matches `b.c`, `b.c.d` but not `a.b.c` or `b.ccc`
* `a` – matches `a`, `a.b`, `a.b.c` but not `aaa` or `aaa.b`
* `b.c` – matches `b.c`, `b.c.d` but not `a.b.c` or `b.ccc`

If more than one filter matches a given category name, the most specific filter is used.

### Additional Attributes

As described in previous sections, certain log message attributes, such as a timestamp, are automatically added to all generated messages. The library also defines some attributes that can be used for application-specific needs:

* `code` : arbitrary integer value (e.g. error code)
* `details` : description string (e.g. error message)

```cpp
// EXAMPLE - specifying additional attributes

SerialLogHandler logHandler;

int connect() {
return ECONNREFUSED; // Return an error
}

void setup() {
Log.info("Connecting to server");
int error = connect();
if (error) {
// Get error message string
const char *message = strerror(error);
// Log message with additional attributes
Log.code(error).details(message).error("Connection error");
}
}

void loop() {
}
```

The example application specifies `code` and `details` attributes for the error message, generating the following logging output:

`0000000084 [app] INFO: Connecting to server`
`0000000087 [app] ERROR: Connection error [code = 111, details = Connection refused]`

### Log Handlers

In order to enable logging, application needs to instantiate at least one log handler. If necessary, several different log handlers can be instantiated at the same time.
Expand Down Expand Up @@ -8631,7 +8667,7 @@ Parameters:

### Logger Class

This class is used to generate log messages. The library also provides default instance of this class named `Log`, which can be used for most of the logging operations.
This class is used to generate log messages. The library also provides default instance of this class named `Log`, which can be used for all typical logging operations.

`Logger()`
`Logger(const char *name)`
Expand Down Expand Up @@ -8675,12 +8711,25 @@ Parameters:

* format : format string

`void operator()(const char *format, ...)`
`void log(const char *format, ...)`
`void operator()(const char *format, ...)`

```cpp
// EXAMPLE
Log("This is %s message", "info");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would change the "info" parameter in case someone confuses it with actually setting the logging level. Something like

Log("The secret of everything is %d", 42);

```

Generate log message with the default logging level (`LOG_LEVEL_INFO`).

Parameters:

* format : format string

`void log(LogLevel level, const char *format, ...)`
`void operator()(LogLevel level, const char *format, ...)`

```cpp
// EXAMPLE
Log("This is %s message", "info"); // Uses default logging level
Log(LOG_LEVEL_INFO, "This is %s message", "info");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here - let's use a different format param other than "info" to avoid confusion with logging levels.

```

Expand Down
47 changes: 34 additions & 13 deletions hal/src/gcc/core_hal.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -52,25 +52,32 @@ void setLoggerLevel(LoggerOutputLevel level)
log_level = level;
}

void log_message_callback(const char *msg, int level, const char *category, uint32_t time, const char *file, int line,
const char *func, void *reserved)
void log_message_callback(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved)
{
if (level < log_level) {
return;
}
std::ostringstream strm;
// Timestamp
strm << std::setw(10) << std::setfill('0') << time << ' ';
// Category (optional)
if (category && category[0]) {
if (attr->has_time) {
strm << std::setw(10) << std::setfill('0') << attr->time << ' ';
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we currently don't use the stream classes, since I thought they were quite heavy...do you know what overhead they bring?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the gcc platform)

}
// Category
if (category) {
strm << '[' << category << "] ";
}
// Source info (optional)
if (file && func) {
strm << file << ':' << line << ", ";
// Strip argument and return types for better readability
std::string funcName(func);
const size_t pos = funcName.find(' ');
// Source info
if (attr->has_file && attr->has_line && attr->has_function) {
// Strip directory path
std::string fileName(attr->file);
size_t pos = fileName.rfind('/');
if (pos != std::string::npos) {
fileName = fileName.substr(pos + 1);
}
strm << fileName << ':' << attr->line << ", ";
// Strip argument and return types
std::string funcName(attr->function);
pos = funcName.find(' ');
if (pos != std::string::npos) {
funcName = funcName.substr(pos + 1, funcName.find('(') - pos - 1);
}
Expand All @@ -79,7 +86,21 @@ void log_message_callback(const char *msg, int level, const char *category, uint
// Level
strm << log_level_name(level, nullptr) << ": ";
// Message
strm << msg;
if (msg) {
strm << msg;
}
// Additional attributes
if (attr->has_code || attr->has_details) {
strm << " [";
if (attr->has_code) {
strm << "code = " << attr->code << ", ";
}
if (attr->has_details) {
strm << "details = " << attr->details << ", ";
}
strm.seekp(-2, std::ios_base::end); // Overwrite trailing comma
strm << "] ";
}
std::cout << strm.str() << std::endl;
}

Expand Down Expand Up @@ -117,7 +138,7 @@ extern "C" int main(int argc, char* argv[])
if (exists_file(eeprom_bin)) {
GCC_EEPROM_Load(eeprom_bin);
}
app_setup_and_loop();
app_setup_and_loop();
}
return 0;
}
Expand Down
Loading