Unified logging - String Based #5965

deepikabhavnani · 2018-01-29T23:16:12Z

~~This PR is work in progress, to get inputs from mbed-os team on logging levels and API's.~~

This logging system is designed to provide simple API's to log information from different modules on UART or other stream capable devices.

ID based tracing is supported in which strings are replaces with ID's and host tool will be required to decode ID and print messages.

Log Levels supported are: Critical, Error, Warning, Debug, Info and Trace.

Circular buffer is used to save log data, which is then redirected to UART module. API's are thread safe and can be used in ISR context.

Update the implementation, based on inputs from various teams. This PR is only for string based implementation.

0xc0170 · 2018-01-30T10:34:13Z

Having logging 💯

@deepikabhavnani mbed_trace that is in mbed OS in PAL feature folder - what are differences between this new logger and the another trace library?

deepikabhavnani · 2018-01-30T15:10:48Z

@0xc0170 - Our goal with this logging system is mentioned below, all of that is not supported by mbed_trace.

To provide single interface to log all data via different channels ( UART / filesystem / network). We will be adding data to buffers which will then be redirected.
Support logging from ISR
ID based tracking

geky

Just some comments. I realized there is still a lot of work for this pr, so feel free to respond to them when convenient.

geky · 2018-01-30T17:40:06Z

platform/logger_api.h

+#if MBED_ID_BASED_TRACING
+#define info(mod, fmt, ...)   MBED_LOG_ID_1(1, __COUNTER__, mod LOG_INFO FILE_INFO FMT_SEP fmt, ##__VA_ARGS__)
+#else
+#define info(mod, fmt, ...)   MBED_LOG_STR_1(1, "%-4.4s" LOG_INFO FILE_INFO FMT_SEP fmt, mod, ##__VA_ARGS__)


What if we used the mbed prefix?

mbed_debug()

mbed_info()

mbed_warn()

mbed_error()

That way we would avoid creating name conflicts in user code, and we could change the exit behaviour of error (which is incompatible with the error logging level) without breaking backwards compatibility.

geky · 2018-01-30T17:42:54Z

platform/logger_api.h

+ */
+
+#ifndef MBED_LOGGER_API_H
+#define MBED_LOGGER_API_H


Not sure this file should be named mbed_logger_api.h. Usually *_api.h files are HAL files, otherwise aren't all header files api files?

We have few api files in platform as well. Naming is not issue (suggestions welcome), I need two header files, one which will be added to "mbed.h" and other internal

You could name it mbed_logger_internal.h. I think that's more clear.

Although you could just have all the macros in on big header file. IMO fewer files makes it easier to find things. Less jumping around. Also moving utilities to mbed_preprocessor.h would help reduce what you see in the file.

internal header file that reduces scope for internal things sounds good. That would answer also the question above about #define LOG_ERR_CRITICAL SEPARATOR "C" SEPARATOR.

Internal header files can reside in same directory?

geky · 2018-01-30T17:44:28Z

platform/logger.c

+    va_end(args);
+}
+
+void log_id_data(uint8_t argCount, ...)


This shouldn't be compiled unless id logging is enabled

geky · 2018-01-30T17:46:17Z

platform/logger.h

+#define LOG_WARN                SEPARATOR "W" SEPARATOR
+#define LOG_DEBUG               SEPARATOR "D" SEPARATOR
+#define LOG_INFO                SEPARATOR "I" SEPARATOR
+#define LOG_TRACE               SEPARATOR "T" SEPARATOR


These may be confusing. My first thought was to call MBED_LOG(LOG_WARN, "blablablah"). Maybe they should be prefixed with LOG_FMT_WARN?

Defines/macros in logger.h should not be used end user, hence created *_api.h.
These strings are for internal purpose, for user it will be different API for different levels and levels are not passed as args.
It will be warn("blah") / mbed_warn("blah")

Hm, one solution is to use a trailing underscore to imply internal use (LOG_WARN_). @pan-, thoughts on naming internal macros?

geky · 2018-01-30T17:47:56Z

platform/logger.h

+
+// Count the arguments in macro
+#define GET_NTH_ARG(_1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, N, ...)   N
+#define COUNT_VARARGS(...)      GET_NTH_ARG(__VA_ARGS__, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1)


These may cause conflicts in the header file. We should prefix them with MBED_ or something.

Also should we move them to mbed_preprocessor.h?

This and GET_STRING may be moved to mbed_preprocessor.h.

pan- · 2018-01-30T18:49:09Z

@deepikabhavnani I have few questions:

Is there a plan to have a tool running on the client side that filters module and log format (or something on the host side) ?
Will it be possible to select the stream that is used to transfer the log
*printf has no customization points; it may be difficult/resource expensive to properly format an entry (as an example consider logging the content of an array in a single line). Have you considered a mechanism that would allow the extension of the logging framework with a C++ stream like (<<) interface ?
How will you tackle concurrent logs overlapping ?

jupe · 2018-01-30T21:01:46Z

Why not to extend current mbed-trace library for new needs? Actually some of those features are possible to do already top of mbed-trace ;)

ohagendorf · 2018-01-31T14:20:25Z

@deepikabhavnani may I remind you about the Event Recorder system #4917?
It would be a good part of a logging system.

deepikabhavnani · 2018-01-31T15:34:33Z

@pan-

ID based tracing will need a tool on host side (can be extended to client side) which can filter along with decoding, but no tool is planned for print based method.
We have not thought of C++ stream approach, but can discuss this offline.
Can talk on this
Log overlapping - Experimenting with different things, will provide more info on that later.

deepikabhavnani · 2018-01-31T15:39:23Z

@jupe We can extend mbed-trace library for few features, but ID based approach cannot be added with backward compatibility.
In case of ID based, we are trying to replace all debug strings with single unique ID, and no debug strings will be present in binary.

deepikabhavnani · 2018-01-31T15:44:30Z

@ohagendorf - Event recording system will be good candidate for tracing (ftrace type, no need for user to add debug code entry/exit and timing spent will be reported) functionality, not planned for now.

geky · 2018-01-31T17:40:07Z

@jupe, qq, where do the features of mbed-trace live? On the API side or the log encoding side? Maybe we can merge these two projects to get the features of both?

JanneKiiskila · 2018-02-01T15:58:11Z

platform/logger.c

@@ -0,0 +1,51 @@
+/* mbed Microcontroller Library
+ * Copyright (c) 2006-2013 ARM Limited


Copyright year should be 2018, since it's now 2018.

jupe · 2018-02-01T21:05:05Z

Some thoughts..

all of that is not supported by mbed-trace

To provide single interface to log all data via different channels ( UART / filesystem / network). We will be adding data to buffers which will then be redirected.

In fact embed-trace is very general purpose and abstract since it is used quite widely already across tens of libraries and test applications we have - also in other OS's. Mbed-trace have internal buffer as well. Trace lines are constructed by internal method for now but could be done different way as well - eg format what ever style we/user wants, e.g. minimise trace lines or even consume binary traces. Output channel is also flexible, by default it uses stdout which are redirected to serial port in mbed-os but can be redirected to file or socket very easily - it's application decision where it want's to pipe traces.

Support logging from ISR

I’m not sure should we even ever log from ISR even it could help sometimes because it could cost unexpected behavior - especially time critical connectivity scenarious. At least then tracing have to be very very “cheap”..

ID based tracking.

I would like to see solution where "dictionary" (=mapping table between id <->string) are global - not build specific - because it will cost a lot if every builds have own dictionary. We most probably need to start collecting those dictionaries to some centralised place in some point - if each build have own dictionary this collection start increasing so much (build uid<->dictionary) that it will be hard to manage over the time. Also it might becomes support headache if dictionaries doesn't correspond to build/"minimised" trace output...
Another challenge with this is (like with binary tracing) that we have to provide very flexible decode tools in client side which are easy integrate to different test frameworks we/other uses - it's not simple thing either. These are probably needed anyway right after we decide to implement "minimised traces" way or another - it just need to plan well so that every stakeholders understand its consequences.

@jupe - Thanks for your feedbacks, btw, I think you answered your own concern, sort of. We are keeping the dicts build specific so that
there is no need to take care of id conflicts and there is no maintenance issues like keeping/updating the ids on a centralized point as you mentioned. Yes, there will be tools developed to decode the trace on client side. Please let us know what "flexibility" you are expecting so that we can incorporate that into those tools. For 5.8 release, we are not planning to support ID based tracing completely, it will be captured in future releases, so we can accommodate your feedbacks when we start implementing the tools.
As you might have noticed we will eventually have String based tracing and ID based tracing. String based tracing will be more user friendly without need for special client side tools whereas ID based tracing will be optimized and performance friendly but less user-friendly. I expect people to use ID based tracing in release builds to have minimal impact on CPU cycles. For normal development we can use String based tracing which works more like traditional tracing mechanisms.

deepikabhavnani · 2018-02-01T21:37:43Z

@jupe Thanks for inputs, we are open to all inputs and suggestions.

At least then tracing have to be very very “cheap”..

We are trying our best to do that with ID based tracing where minimum data bytes will be buffered and in future re-direct data to filesystem/network/anything lighter then serial

build uid<->dictionary

Current plan is to save this dictionary in the binary itself (just move the strings to a section which will not be loaded in either RAm/ROM). We are experimenting and trying few options and yes 100% cannot guarantee that we have all solutions in hand.

This PR is not the final solution, its purpose is to get inputs and understand all available/possible options.

kjbracey · 2018-02-08T15:47:36Z

I'm not immediately seeing why any of the new facilities need a visible API change from the existing mbed_trace implementation for the code making the logging calls. The intent was that that be the universal logging API, and certainly was for mbed OS 3. The API of mbed trace should be viewed separately from its specific implementation.

It was always the intent that if you want to to send the strings somewhere else, just redirect the current implementation's output functions, but if you really wanted to do something radically different for the implementation, such as not have embedded strings in the image at all with macro magic, you could do that.

I think the basic syntax it gives already uses (tr_info("format", args), with the requirement that it is a single line unit, or more fully trace(level, "group", "format", args) is equivalent to yours.

On dictionaries, last time we looked at binary logging (and decided it was too much hassle), I think there was some consensus that if doing it it would make sense to hash the format strings to permit a cumulative dictionary covering all images, rather than maintaining custom dictionaries. A 32-bit hash would likely be sufficient.

Buffering in ISR was just single line, which is not enough and shared queue was used which costed RAM size of 1.5K Instead circular buffer is used for ISR prints, note since prints from user thread and ISR are not logged via same channel will be received out of order. Buffer size is kept limited to support all target devices, but user can configure buffer size to debug ISR specific prints. ISR prints are lossy and in case of full buffer, you will miss entire log message and not partial. Circular buffering is used for all logging messages in case of ID based selection.

With logging feature extra 1K of RAM is needed of which 512 bytes is to buffer ISR data. We have enough RAM space, but in case of IAR static heap/stack size limit us to optimal RAM usage. Change is based on devie RAM memory size: 1. < 16K RAM: Buffer size is reduced in targets.json (MBED_CONF_MAX_BUFFER_SIZE) 2. Memory for circular buffer will be obtained runtime during mbed_boot

For devices <16K RAM, we dont have space to add another thread. Hence giving an option to disable ISR logging completely for them System will not crash or stall during ISR prints, but will simply discard them if printed by logging API's.

1. Correct API arguments and doxygen data 2. Added config options to 'lib.json'

1. Corrected log levels 2. Removed volatile 3. Added critical section to log_buffer_data 4. No prefix/suffix for private static global variables

Created dynamic stack memory for logging thread, and removed define to disable ISR logging. If device does not have sufficient memory for circularBuffer and thread creation, then 1. In case of string base logging - ISR prints will be discarded. 2. In case of ID based logging system will ASSERT

Format string and othe updates to local variables need not be in critical section.

deepikabhavnani · 2018-05-11T18:49:15Z

Rebased to resolve conflicts

In order to enable mbed_trace as default: 1. Config option to disable mbed logging 2. Wrappers for mbed_logging API;s 3. MBED_CRIT - default implementation used, so no need to modify/re-write for mbed_trace

0xc0170 · 2018-05-18T11:27:47Z

Please review Travis failure (events) and also jenkins CI. Both seem to be related to the changes here

deepikabhavnani · 2018-05-18T14:41:04Z

@0xc0170 - Yes some more work is required to make mbed_trace as default, will let you know if any progress is done in that direction.

adbridge · 2018-05-21T14:09:05Z

@deepikabhavnani What is the status on this ? Code freeze for 5.9 is fast approaching...

deepikabhavnani · 2018-05-22T00:11:08Z

@0xc0170 @adbridge - Wont go in 5.9

deepikabhavnani · 2018-05-22T15:22:28Z

Closing this, will be ported later with small updates in another PR

AGlass0fMilk · 2018-07-02T14:06:52Z

Sorry to revive a dead issue, but I stumbled upon this while searching for native mbed trace/logging solutions. Can anyone give an update on the state of this feature? Is there a new issue/PR open for it yet?

Thanks!

deepikabhavnani · 2018-07-02T14:35:23Z

@AGlass0fMilk - We do not have updates for this issue for now, till we have unified solution you can use 'mbed_trace' https://github.com/ARMmbed/mbed-os/tree/master/features/frameworks/mbed-trace.

Feel free to share your inputs and concerns related to tracing/logging, we will try our best to address them when back in track with this issue.

cmonr added the needs: review label Jan 29, 2018

0xc0170 added the do not merge label Jan 30, 2018

0xc0170 requested review from geky and SenRamakri January 30, 2018 10:30

geky reviewed Jan 30, 2018

View reviewed changes

JanneKiiskila reviewed Feb 1, 2018

View reviewed changes

deepikabhavnani force-pushed the unified_trace branch from 4b10b38 to ff8d580 Compare February 13, 2018 19:25

deepikabhavnani removed the do not merge label Feb 13, 2018

deepikabhavnani force-pushed the unified_trace branch from ff8d580 to 57659fa Compare February 13, 2018 19:35

deepikabhavnani changed the title ~~Initial version of Unified logging~~ Unified logging - String Based Feb 13, 2018

deepikabhavnani force-pushed the unified_trace branch 2 times, most recently from 161c767 to c14ea35 Compare February 13, 2018 21:17

deepikabhavnani requested a review from sg- February 13, 2018 21:20

deepikabhavnani force-pushed the unified_trace branch from 5e4e039 to 8f3e773 Compare February 14, 2018 17:22

SenRamakri requested review from SeppoTakalo and yogpan01 February 14, 2018 17:29

deepikabhavnani force-pushed the unified_trace branch 2 times, most recently from c038974 to 9c1f1c5 Compare February 14, 2018 21:40

Deepika added 12 commits May 11, 2018 13:47

Option to disable ISR logging

bff7a98

For devices <16K RAM, we dont have space to add another thread. Hence giving an option to disable ISR logging completely for them System will not crash or stall during ISR prints, but will simply discard them if printed by logging API's.

Corrected NDEBUG guard for logging

7f98dc0

API document + Config options

281ea41

1. Correct API arguments and doxygen data 2. Added config options to 'lib.json'

Addressed review comments

58388d5

1. Corrected log levels 2. Removed volatile 3. Added critical section to log_buffer_data 4. No prefix/suffix for private static global variables

Circular buffer memory creation using malloc instead new

c577eb9

Added eventflags for synchronization

7319abc

Corrected the scope of critical section

820ff14

Format string and othe updates to local variables need not be in critical section.

Correcting wrong macro removal

84ef718

Updated the example as newline char is needed now

136923c

deepikabhavnani force-pushed the unified_trace branch from bd11928 to 136923c Compare May 11, 2018 18:48

Deepika added 3 commits May 11, 2018 14:10

Removed trace level and set info as default log level

a4e1bda

Default Mbed_trace enabled

65d00d0

In order to enable mbed_trace as default: 1. Config option to disable mbed logging 2. Wrappers for mbed_logging API;s 3. MBED_CRIT - default implementation used, so no need to modify/re-write for mbed_trace

Mbed trace enabled as default

1bfb5b1

andrewleech mentioned this pull request May 14, 2018

NRF5x: redirect NRF logging to mbed stdout #6889

Closed

cmonr added the release-version: 5.9.0-rc1 label May 14, 2018

0xc0170 added needs: work and removed release-version: 5.9.0-rc1 needs: review labels May 22, 2018

deepikabhavnani closed this May 22, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unified logging - String Based #5965

Unified logging - String Based #5965

deepikabhavnani commented Jan 29, 2018 •

edited

Loading

0xc0170 commented Jan 30, 2018 •

edited

Loading

deepikabhavnani commented Jan 30, 2018

geky left a comment

geky Jan 30, 2018

geky Jan 30, 2018

deepikabhavnani Jan 30, 2018

geky Jan 30, 2018

0xc0170 Jan 31, 2018

deepikabhavnani Jan 31, 2018

geky Jan 30, 2018

geky Jan 30, 2018

deepikabhavnani Jan 30, 2018

geky Jan 30, 2018

geky Jan 30, 2018

pan- Jan 30, 2018

pan- commented Jan 30, 2018

jupe commented Jan 30, 2018

ohagendorf commented Jan 31, 2018

deepikabhavnani commented Jan 31, 2018 •

edited

Loading

deepikabhavnani commented Jan 31, 2018 •

edited

Loading

deepikabhavnani commented Jan 31, 2018

geky commented Jan 31, 2018

JanneKiiskila Feb 1, 2018

jupe commented Feb 1, 2018 •

edited by SenRamakri

Loading

deepikabhavnani commented Feb 1, 2018 •

edited

Loading

kjbracey commented Feb 8, 2018 •

edited

Loading

deepikabhavnani commented May 11, 2018

0xc0170 commented May 18, 2018

deepikabhavnani commented May 18, 2018

adbridge commented May 21, 2018

deepikabhavnani commented May 22, 2018

deepikabhavnani commented May 22, 2018

AGlass0fMilk commented Jul 2, 2018

deepikabhavnani commented Jul 2, 2018

		@@ -0,0 +1,51 @@
		/* mbed Microcontroller Library
		* Copyright (c) 2006-2013 ARM Limited

Unified logging - String Based #5965

Unified logging - String Based #5965

Conversation

deepikabhavnani commented Jan 29, 2018 • edited Loading

0xc0170 commented Jan 30, 2018 • edited Loading

deepikabhavnani commented Jan 30, 2018

geky left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pan- commented Jan 30, 2018

jupe commented Jan 30, 2018

ohagendorf commented Jan 31, 2018

deepikabhavnani commented Jan 31, 2018 • edited Loading

deepikabhavnani commented Jan 31, 2018 • edited Loading

deepikabhavnani commented Jan 31, 2018

geky commented Jan 31, 2018

Choose a reason for hiding this comment

jupe commented Feb 1, 2018 • edited by SenRamakri Loading

deepikabhavnani commented Feb 1, 2018 • edited Loading

kjbracey commented Feb 8, 2018 • edited Loading

deepikabhavnani commented May 11, 2018

0xc0170 commented May 18, 2018

deepikabhavnani commented May 18, 2018

adbridge commented May 21, 2018

deepikabhavnani commented May 22, 2018

deepikabhavnani commented May 22, 2018

AGlass0fMilk commented Jul 2, 2018

deepikabhavnani commented Jul 2, 2018

deepikabhavnani commented Jan 29, 2018 •

edited

Loading

0xc0170 commented Jan 30, 2018 •

edited

Loading

deepikabhavnani commented Jan 31, 2018 •

edited

Loading

deepikabhavnani commented Jan 31, 2018 •

edited

Loading

jupe commented Feb 1, 2018 •

edited by SenRamakri

Loading

deepikabhavnani commented Feb 1, 2018 •

edited

Loading

kjbracey commented Feb 8, 2018 •

edited

Loading