Proposal for new Logger API supporting structured Data

[christophruethingbmw]

Introduction

Today's logger API only supports logging of formatted strings with even some issues as stated in #431. In my opinion, logging strings is not a good idea in a small embedded system due to several reasons:

• Constructing a string at runtime is CPU expensive. Even optimized implementations will introduce an overhead.
• Storing (especially long) format strings consumes memory in RAM and ROM. Typically, a developer will tend to write readable strings which need to have a reasonable length.
• Transmitting (especially long) strings at runtime costs bandwith on any kind of external channel, for example when sending it in DLT format on an ethernet link.
• Analyzing data later becomes harder and slower because we need to parse strings and extrsct data again to e.g. plot a graph out of it.

To mitigate these issues, we want to propose a new logger API that supports (potentially only) structured data and is inspired by the DLT non-verbose mode. Before sketching the actual API proposal, we want to state some requirements and ideas we based our design on.

• Data should be logged in a structure way to keep overhead in terms of resources (CPU, RAM, ROM, Bandwith, ...) as minimal as possible and be able to analyze the data effeciently.
• The API should be easy to use from an application point of view. The overhead for a developer to log data should be kept as small as possible. We want to encourage anybody to log properly.
• The code-first approach of OpenBSW should be followd, thus we want to avoid code generators if not strictly needed.
• The API should be usable standalone (e.g. in unit tests) and when later integrated into a bigger system based on OpenBSW.
• The API should support different log levels as well as separating data from different applications from each other.

Based on this foundation we propse the following API illustrated by a simple usage example (of course in code-first manner).

API Proposal

Definition of Applications and Contexts

// we can define applications and contexts anywhere suitable where type definitions are allowed

struct CarAccess: public ::openbsw::logger::Application<::openbsw::logger::Abbreviation("CAAC")> {};
struct Authentication: public ::openbsw::logger::Context<CarAccess, ::openbsw::logger::Abbreviation("AUTH")> {};

The application and context are similar to the ones in the DLT specification. A log message will be send within a context which again belongs to an application. For both application and context a logger implementation can specify additional data using e.g. specialized templates to for example defining unquite ids, limit the number of log messages, specify queues to use, ...

Definition of Structured Data

// we can define structures anywhere suitable where type defintions are allowed
//    => it needs to inherit from the Message struct and provide a context, a log level and a (within the context) unique id

struct AuthEnd : public ::openbsw::logger::Message<Authentication, ::openbsw::logger::LogLevel::DEBUG, ::openbsw::logger::HashedId("AuthEnd")>
{
    // 2.1 the structure can define the necessary data it wants to log using simple datatypes like standard types, enums, ...
    uint8_t transactionId;
    AuthType authType;
    uint32_t authData;

    // 2.2 the structure can define an optional format method used e.g. for unit testing to print a readable representation
    void format(char *buffer, size_t size)
    {
        std::snprintf(buffer, size, "authentication for transaction %u with data %u", transactionId, authData);
    }
};

A struct is used to define the structured data to log. It is a plain struct iheriting from the Message struct and contains data members for data to log. These data members can theoretically use arbitrary data types but we should restrict this to simple types which we can later also properly interpret.

The struct also need to specify a unique id within the context it belongs to. Since the context has a limited scope in control of a single component, it should be possible to manage uniqness easily. To simplify this even further, we provide the HashedId which calculates a compile-time hash of a string which is used as id. Generating unique strings is even easier then generating unique numbers. Specifying the id manually and not having logic to automatically enumerate all structs is also done by intention to keep ids as stable as possible between different software versions.

In addition to data members we also allow a format method which can be for example used in unit tests to print a readable representation.

Note, that you do not need to define the struct in a specific place, you can place it wherever type definitions are allowed and you can even keep it local in a function where you also call the log function shown below. Also note, that we could provide a simple macro to shorten the source code and always add attributes like packed.

Logging of Data

// we can then log data using different variants of the log functions

// 1. using variadic template arguments
::openbsw::logger::log<AuthEnd>((uint8_t)1U, AuthType::END, 0xaffedeadU);

// 2. using a fill function
::openbsw::logger::log<AuthEnd>([](AuthEnd& m) {
    m.transactionId = 1U;
    m.authType = AuthType::END;
    m.authData = 0xaffedeadU;
});

// 3. passing an already instantiated struct
AuthEnd authEnd;
authEnd.transactionId = 1U;
authEnd.authType = AuthType::END;
authEnd.authData = 0xaffedeadU;
::openbsw::logger::log(authEnd)

Once a struct as shown above is defined, the application can simply log data by filling the data members and calling the log function. We can provide different variants for different use-cases as illustrated above. I think the second one using a fill function can be quite convenient because it avoids the need to define a local variable, it allows to use arbitrary operations to fill the struct (e.g. also a memcpy) and it can optimize away the logic to fill the struct members in case e.g. the log level is deactivated. The fill function will only be called when the log is really taking place, otherwise it can be skipped all together.

Offline Processing

We are not focussing on the internal implementation for now, but when considering for example that we send the data out via non-verbose DLT frames, we need to later interpret them properly. Therefore, we need to think on how to extract the necessary information for tools to display the data This includes

• Mapping of ids (application + context + message id) to the actual structures.
• Interpreting the binary data in the proper structure, basically knowing the memory layout of the structs, the data members and their types.

Since we do not have a DSL but define our structs directly in C++ code we need to somehow extract this information. The proposal we want to make is to use the debug data embedded into the generated elf to retrieve this information. The debug data contains the definition of all (used) structs and also knowns about their memory layout, that's also how a debugger shows data in a readable form. We can use this data and provide a generator that can extract the necessary information from an elf and transform it in a representation tools need it (e.g. a fibex file).

Doing so has the advantage, that the generator is only a post-processing step and can be performed on any elf file. It is not a prerequisit to run the generator to be able to compile the source code.

Demonstrator

A simple and compileable example is here: christophruethingbmw/openbsw-logger-api

[simon-d-bmw]

Thanks for the detailed proposal and the compileable demo — the core idea of typed message structs with compile-time IDs mapping to DLT non-verbose mode is compelling and addresses the right set of problems.

A few observations from looking at the demo code:

std::function in logFill
std::function<void(M&)> involves heap allocation and virtual dispatch, which is problematic for embedded. Since the callable is used immediately and never stored, a plain template parameter is sufficient and zero-overhead:

template <typename M, typename F>
void logFill(F&& fill)
{
    M m{};
    fill(m);
    log(m);
}

Log level filtering
The Level constant exists on Message but is never checked in the demo. For embedded use, compile-time filtering of lower-priority levels is a must-have and should be part of the API design from the start.

Hash collision detection
hash16 produces 16-bit values with no compile-time collision check. Two messages in the same context colliding would be a silent runtime bug. A static assertion to detect duplicates at compile time would make this safe.

__attribute__((packed)) enforcement
This needs to be specified at every message struct definition and is easy to forget. A static_assert in the Message base or a wrapper macro could enforce it.

logArgs fragility
The aggregate initialization M m { {}, std::forward<A>(args)... } is order-dependent and breaks silently if fields are reordered. The logFill variant is safer in practice — worth considering whether logArgs is worth keeping.

Also note the MESSAGE macro references rcore::logger instead of openbsw::logger, so it's currently broken.

Overall this is a solid foundation. I also closed #431 (vararg API redesign) in favour of this proposal, since doing an intermediate cleanup of the old API would be wasted effort once this lands.

[christophruethingbmw]

Hi @simon-d-bmw , thank you for the response, let me try to answer:

1. std::function in logFill
Yes for sure, that's just for the purpose of demonstrating the idea. In the end we should use ETL for this and of course, heap allocation must be avoided.

2. Log level filtering
Until now I did not think of compile time filtering but more of runtime filtering and keep all log levels supported. But I think with a proper template-meta-programming that should be even possible.

3. Hash collision detection
I fear at compile time we cannot really do this because the messages can be scattered over multiple translation units. The idea would be that the final generator (parsing the debug data in the elf) can check for it. Except that, developers need to make sure that no collisions happen. I can tell, that in the past years we used a similar approach in production and actually never ran into an issue.

4. __attribute__((packed)) enforcement
So I think in case sombeody forgets it it is not functionally a problem, the potential padding is just a little bit inefficient. I was already thinking of a macro for definition of message structs to ensure everybody is doing it in the same way. But I also found it nice that we do not rely on such things like packing attributes.

5. logArgs fragility
Yes, I fully agree, maybe we should not provide such a method. It's like aggregate initialization when defining a struct variable. I think using mechanisms like the fill function are more safe and maybe we should only support these.

[simon-d-bmw]

Update regarding 2. Log level filtering:

Compile-time filtering does not provide significant benefits. Efficient run-time filtering is much more important.