RFC: adjust policies and introduce new macros for logging strings

[andrewboie]

The mechanism we have right now for logging strings will not work in an environment where the format strings for log messages have been stripped out of the binary. The binary logging backend will only be able to log the address of the log message format string (to identify it for later offline post-processing), and the raw values of the arguments supplied.

If a transient string is logged, we have some problems. The format string is unavailable, which does not allow us to identify at runtime that a particular parameter is a string that needs to be logged. We will only be able to log its raw pointer value. If the pointer value isn't a ROM string we won't be able to look it up what the string is during post-processing.

I propose we make the following changes:

• Forbid logging transient strings (defined as any string pointer whose address is not within the image ROM) using %s in log messages. For logging where the backend creates the formatted log messages at runtime, we can enforce this with a runtime check. Remove the log_strdup() API.
• Introduce new logging macros, for various severity levels, to specifically emit a transient string to the log. This type of macro will have special properties, it will know that its argument is a transient string, so it will automatically have strdup() called on it, and the backend will emit the string data to the log instead of just a pointer value.
• Introduce another set of macros for dumping binary objects to the log. These take a pointer and a size.

@nordic-krch what do you think of this?

[andrewboie]

Example, just to show what I mean, I don't care too much what the interface looks like:

// desc is a constant string describing what's logged
// followed by any number of transient string pointers
#define LOG_STR_DBG(desc, ...) ...

void foo(char *name, char *job) {
	LOG_STR_DBG("foo called with", name, job);
    k_free(name);
    k_free(job);
}

In the log:

[00:00:00.510,000] <dbg> os: foo called with 'fred', 'manager'
[00:00:00.510,000] <dbg> os: foo called with 'mary', 'developer'

[andrewboie]

@nordic-krch actually perhaps there is a way we can solve this without changing the interface.

What if log_strdup() returned a string pointer that had the lowest bit set, as a marker that this is a transient string. we can use the low 2 bits for flags since they will be at least 4 byte aligned. this gets saved with the event.

When the backend looks at the event arguments, it will note that the low bit is set, and that will be a trigger to dump the string value out to the log data instead of logging its pointer value.

If the backend formats the messages at runtime, naturally it will clear the low bit before actually dereferencing the string pointer argument.

[nordic-krch]

Regarding reducing log message footprint and removing log message strings from the binary. I'm not that good in linking/elf stuff but i was wondering if it would be possible to store those strings in a section which would not go into binary but would stay in elf. Then on PC it would be possible to decode logs with access to elf file.

Regarding transient strings handling: it may be based on PR i hope at some point will get merged (#17367). There i proposed a change where no only strings but also any other structs can be duplicated, e.g. instead of formatting ble address before passing it to string you create object with ble address and formatting function and formatting happens during log processing. Object are allocated from the same pool as log messages (there is no need for custom pool for log_strdup). With that in mind, logger argument will contain a pointer to element from log message buffer pool.
Backend that handles stringless case would send main message and referenced one to the host (if argument is identified as address of element from the pool). Host can resolve it to human readable version.

There is one risk with that however. Log argument can have value which matches address of element from the pool and it might not be it. This can be solved on host side. Whenever reference candidate is detected we send additional object and on host side when forming human readable version format specifier will help to determine if reference should be treated as value or as address to an object.

[andrewboie]

What if log_strdup() returned a string pointer that had the lowest bit set, as a marker that this is a transient string. we can use the low 2 bits for flags since they will be at least 4 byte aligned. this gets saved with the event.

Disregard, this won't work.

I'm not that good in linking/elf stuff but i was wondering if it would be possible to store those strings in a section which would not go into binary but would stay in elf. Then on PC it would be possible to decode logs with access to elf file.

Yeah that should be doable.

Regarding transient strings handling: it may be based on PR i hope at some point will get merged (#17367). There i proposed a change where no only strings but also any other structs can be duplicated, e.g. instead of formatting ble address before passing it to string you create object with ble address and formatting function and formatting happens during log processing. Object are allocated from the same pool as log messages (there is no need for custom pool for log_strdup). With that in mind, logger argument will contain a pointer to element from log message buffer pool.
Backend that handles stringless case would send main message and referenced one to the host (if argument is identified as address of element from the pool). Host can resolve it to human readable version.
There is one risk with that however. Log argument can have value which matches address of element from the pool and it might not be it. This can be solved on host side. Whenever reference candidate is detected we send additional object and on host side when forming human readable version format specifier will help to determine if reference should be treated as value or as address to an object.

But if it's a reference candidate, don't you have to dump out its contents to the log? What happens if it tries to do that with a value it thinks is a pointer within the pool when it isn't?

Regarding transient strings handling: it may be based on PR i hope at some point will get merged (#17367)

I haven't had time to look at that one yet, but doing this by introducing new format strings will not be able to validate at compile time with __printf_like(), and exacerbates the usage of stdarg.h which is required to not be used by MISRA-C. You need to talk to @ceolin and other fusa stakeholders.

[nordic-krch]

I haven't had time to look at that one yet, but doing this by introducing new format strings will not be able to validate at compile time with __printf_like()

It using same approach a linux does (i heard) it's using %pZ format specifier for for __printf_like check it's just %p.

[nordic-krch]

but the fact is that in that PR it is freeing allocated message based on %pZ format specifier found in the string so if it's not accessible then we have a problem.

[aescolar]

@andrewboie @nordic-krch Thanks for thinking about this.

I would wonder if dynamically generated strings in the embedded side would not be better avoided altogether, due to their overhead.
A BT address is 7 bytes, not 30 chars (or whatever it is printed as).

What about the idea of doing something a bit more radical, for a lean logger version which does the absolute minimum in the embedded side:
Log the program counter of the line where the logger call occurs. As well as any parameter to the log call, but not the format string.
Generate (separately from the embedded binary) a table recording the format string for each logger program counter. The computer side log parser uses this to convert out the logged bytes to a human readable log.
Have some format specifiers for MAC addresses (or any other thing you typically need to log).
If somebody actually logs a string with %s, frown at them, but actually log the string itself (you cant do better not knowing more).

Edit: after reading @andrewboie and @nordic-krch comments I realized I mostly repeated what they said here. Sorry for that noise.
Anyhow, the idea I presented about of using the program counter as identifier for the format string would probably not be too good, as a) we would need a reliable way of getting it for all architectures, and b) we do not necessarily know where the code will be placed depending on what developers do with the elf.

[nordic-krch]

For things like Bluetooth address and MAC address (probably majority of string duplicates) we could have them stored as arguments in the log message and create custom specifiers:

LOG_INF("address: %pZb1%pZ2", (void *)((u32_t *)&addr)[0],  (void *)((u32_t *)&addr)[1]));

where %pZb1 means part1 of bluetooth address.

this off course looks awful but would store 7 byte address into 2 32bit log arguments and then formatter would print it nicely. That is the best solution in terms of memory and performance. We can add markers like #define BLE_ADDR_FSPEC "%pZb1%pZ2" and #define BLE_ADDR_STRARG(addr)

then you have something like:

LOG_INF("address: "BLE_ADDR_FSPEC" rest of string", BLE_ADDR_STRARG(addr));

that would be also applicable to printk. Similar approach could be taken for MAC address. What do you think?

I agree with @aescolar that transient strings might need to be discarded for this limited logger mode.

[nordic-krch]

Another thought:

Not sure if that is too unuser-friendly but if string formatting is extended to support something like:

• %pcw - print word as characters until NULL is found.
• %pcc - continued printing of word as characters. if in previous %pcw or %pcc had NULL omit it

Then if transient string is of known size (e.g. declared on stack in the function) there could be a macro which would expand TSTR_FSPEC(len) to sequence of %pcw%pcc...%pcc and macro TSTR_ARG(str,len) which would be resolved to *(u32_t *)&str[0], *(u32_t *)&str[4], ..... Such string would be stored directly in the log message (good memory utilization and suitable for stringless logging).

u8_t buf[20];
sprintf(buf,...);
LOG_INF("my string" TSTR_FSPEC(sizeof(buf)) "my string part2", TSTR_ARG(buf, sizeof(buf));

Limitations:

• max number of arguments in the log (currently 15) - 60 byte string limit
• max string size must be known at compile time

[aescolar]

that would be also applicable to printk. Similar approach could be taken for MAC address. What do you think?

Would it be enough to know the BT address is always 7 consecutive bytes in memory? (so only 1 format specifier?)
LOG_INF("A very long string with a BT address %pBTA in the middle", (void*)&bt_address);
And the logger would copy those 7 bytes towards whichever backend it uses.

[nordic-krch]

logger is not analyzing string when creating a log message, just copies sizeof(void *) arguments and forms a message. If it is split into multiple standard arguments then logger would treat them without any special approach.

[jukkar]

I would prefer if we do not put any special treatment for MAC addresses like assuming that they are certain length etc. For example in networking code the MAC/link address address can be from 2 to 8 bytes long.

[aescolar]

@jukkar Do you know in a particular logging statement the size of the MAC address you want to log (number of bytes of the address, not the expanded string)

[andrewboie]

But if it's a reference candidate, don't you have to dump out its contents to the log? What happens if it tries to do that with a value it thinks is a pointer within the pool when it isn't?

Still need this question answered.

I don't think this design is workable. You feed it a value which it thinks is an object, it will then start writing potentially arbitrary memory to the log stream, and then attempt to free it out of the pool.

I think there should be dedicated APIs for logging strings or binary data. It is the safest way to do this. I don't see the current design as workable when the format strings are not available at runtime. When logging data, we either need a pointer/size pair, or reliable knowledge that we are working with a C string.

[aescolar]

I think there should be dedicated APIs for logging strings or binary data[...]. I don't see the current design as workable when the format strings are not available at runtime

I do agree about this.

[jukkar]

Do you know in a particular logging statement the size of the MAC address you want to log (number of bytes of the address, not the expanded string)

Yes, the size of the link address is known when printing it.

[nashif]

@nordic-krch should we close this? was it addressed in the overhaul?