Remove repetition of metadata in log messages #2953

aggarw13 · 2021-01-26T01:03:59Z

Problem

Problem 1: Metadata is duplicated in log messages

With the refactored libraries using the new logging macros (LogError, LogInfo, LogWarn, LogDebug), the log messages from the libraries contain duplication of task name and tick count metadata which makes the log messages non-readable. The cause of the metadata repetition is that each of the LogXXXX calls results in 3 calls to vLoggingPrintf, due to which the metadata is repeated in each call.
Here is an example of logs from the coreMQTT library when running the core_mqtt_mutual_auth demo:

[INFO] [MQTT] [core_mqtt.c:886] 4 34300 [iot_thread] Packet received. ReceivedBytes=2.5 34302 [iot_thread] 
[INFO] [MQTT] [core_mqtt_serializer.c:970] 6 34308 [iot_thread] CONNACK session present bit not set.7 34310 [iot_thread] 
[INFO] [MQTT] [core_mqtt_serializer.c:912] 8 34314 [iot_thread] Connection accepted.9 34316 [iot_thread] 
[INFO] [MQTT] [core_mqtt.c:1563] 10 34322 [iot_thread] Received MQTT CONNACK successfully from broker.11 34324 [iot_thread] 
[INFO] [MQTT] [core_mqtt.c:1829] 12 34328 [iot_thread] MQTT connection established with the broker.13 34332 [iot_thread]

Problem 2: Log messages are out-of-order when `LogXXXX` macros are called in multi-threaded environment

The implementation of logging_stack.h makes 3 calls to vLoggingPrintf which are vulnerable to context-switch before the completion of the 3 calls.
Here is an example of mangled logs from the MQTT connection sharing demo that contains log calls from multiple tasks:

125 21323 [Subscriber] [INFO] [MQTTDemo] [mqtt_demo_connection_sharing.c:2042] 126 21323 [Subscriber] Received publish on topic filter/sync/1
Message payload: Hello World! Sync: 1
168 21667 [SyncPublisher] [INFO] [MQTTDemo] [mqtt_demo_connection_sharing.c:1832] 173 21768 [AsyncPublisher] [INFO] [MQTTDemo] [mqtt_demo_connection_sharing.c:1914] 174 21768 [AsyncPublisher] Adding publish operation for message Hello World! Async: 4 
on topic filter/async/4175 21768 [AsyncPublisher] 
176 21868 [iot_thread] [INFO] [MQTT] [core_mqtt.c:885] 177 21868 [iot_thread] Packet received. ReceivedBytes=39.178 21868 [iot_thread]

Solution

This PR fixes the problem by refactoring the macro layer implementation in logging_stack.h to call the logging function (exposed by iot_logging_task.h) only once instead of 3 times.
This PR refactors simplifies the implementation by removing the metadata addition logic for the ISO C90 compliant code. In addition, it also adds support for ISO C99 (with GNU extension) standard to show how extra metadata of source library, file location can be added with simple variadic macro logic.
The library can be configured with either of the C90 or C99 implementations a new macro LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION.

After the fix, the above logs from coreMQTT library look like:

10 34340 [iot_thread] [INFO] [MQTT] [core_mqtt.c:886] Packet received. ReceivedBytes=2.
11 34344 [iot_thread] [INFO] [MQTT] [core_mqtt_serializer.c:970] CONNACK session present bit not set.
12 34350 [iot_thread] [INFO] [MQTT] [core_mqtt_serializer.c:912] Connection accepted.
13 34356 [iot_thread] [INFO] [MQTT] [core_mqtt.c:1563] Received MQTT CONNACK successfully from broker.
14 34362 [iot_thread] [INFO] [MQTT] [core_mqtt.c:1829] MQTT connection established with the broker.

libraries/logging/iot_logging_task_dynamic_buffers.c

…dkAssembleAndLog macro

…/amazon-freertos into poc/logging-thread-safety-issue

nateglims · 2021-01-27T23:59:17Z

/bot run checks

nateglims · 2021-01-28T00:05:26Z

/bot run checks

nateglims · 2021-01-28T00:08:49Z

/bot run checks

nateglims · 2021-01-28T00:10:49Z

/bot run checks

nateglims · 2021-01-28T00:14:28Z

/bot run checks

…pied for enqueing and processing in logging task

…tions

libraries/logging/README.md

leegeth · 2021-02-04T19:54:28Z

libraries/logging/include/logging_stack.h

+    #endif
+
+    #define SdkLogError( message )           SdkLogErrorC99 message
+    #define SdkLogErrorC99( format, ... )    vLoggingPrintf( "[ERROR] [%s] [%s:%d] " format "\r\n", LIBRARY_LOG_NAME, FILENAME, __LINE__, ## __VA_ARGS__ )


I think it will be better to keep the metadata format and metadata as another MACRO similar to how it was. This will have Single source of truth for metadata information.

libraries/logging/iot_logging_task_dynamic_buffers.c

aggarg · 2021-02-06T22:27:16Z

libraries/logging/README.md

@@ -0,0 +1,109 @@
+## Sample Implementation of Logging Interface
+
+This library provides reference implementations of the [logging interface](#the-logging-interface) that is used by FreeRTOS libraries and demos to generate log messages. This library provides


I assume that the word "library" will be changed to sample/demo when you move it to demos folder.

I have changed the wording to "sample" now itself :)

aggarg · 2021-02-06T23:08:06Z

libraries/logging/README.md

@@ -0,0 +1,109 @@
+## Sample Implementation of Logging Interface


Sample Implementation of Logging Interface

This library provides reference implementations of the
logging interface that is used by FreeRTOS libraries
and demos to generate log messages. This library provides implementations for
both ISO C90 standard and ISO C99 standard (with GNU extension) of the logging
interface.

Note: Users can provide their own implementations of the logging interface
to enable logging, if they choose to not use this implementation.

To enable logging using the sample implementation for a FreeRTOS library and/or
demo:

Configure logging level by defining LIBRARY_LOG_LEVEL macro to one of
LOG_NONE, LOG_ERROR, LOG_WARN, LOG_INFO, LOG_DEBUG.

If using the ISO C99 (with GNU extension) implementation (which is default),
define LIBRARY_LOG_NAME to configure the library name which is prepended to
the log messages.

If your compiler only supports the ISO C90 standard, use the C90
implementation by setting the LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION
macro to 0.

The logging file include and macro definitions must follow the following order:

Include logging_levels.h.

Define LIBRARY_LOG_LEVEL, LIBRARY_LOG_NAME, and
LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION as mentioned above.

Include logging_stack.h.

A sample logging configuration for the coreMQTT library which is defined in
core_mqtt_config.h file:

#include "logging_levels.h" #ifndef LIBRARY_LOG_NAME #define LIBRARY_LOG_NAME "MQTT" #endif #ifndef LIBRARY_LOG_LEVEL #define LIBRARY_LOG_LEVEL LOG_INFO #endif #include "logging_stack.h"

The above configuration results in the logging messages looking like the following.
Note that the library name ([MQTT]) and source file location ([core_mqtt.c:1175])
are prepended to each log message.

78 1950 [iot_thread] [INFO] [MQTT] [core_mqtt.c:886] Packet received. ReceivedBytes=2. 79 1950 [iot_thread] [INFO] [MQTT] [core_mqtt.c:1162] Ack packet deserialized with result: MQTTSuccess. 80 1951 [iot_thread] [INFO] [MQTT] [core_mqtt.c:1175] State record updated. New state=MQTTPublishDone.

If ISO C90 implementation is used (i.e. LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION
is defined to 0), the logging messages look like the following. Note that the
library name and source file location are not present in each log message.

78 1950 [iot_thread] [INFO] Packet received. ReceivedBytes=2. 79 1950 [iot_thread] [INFO] Ack packet deserialized with result: MQTTSuccess. 80 1951 [iot_thread] [INFO] State record updated. New state=MQTTPublishDone.

Using your custom implementation of Logging Interface

The Logging Interface comprises of the following 4 logging macros, listed in
increasing order of verbosity:

LogError

LogWarn

LogInfo

LogDebug

LogError is only called when there is an error and so is the least verbose,
whereas LogDebug is called more frequently to provide debug level information
and is therefore, the most verbose.

An implementation of the logging interface needs to define these macros to
map them to their logging implementation. Logging macros use format specifier
and variable number of arguments, just like standard library printf function
but they use double parenthesis to support ISO C90 which should be taken care
while defining them.

An example call of the logging macros is the following:

LogInfo( ( "This prints an integer %d", 100 ) );

If you have a thread safe printf function, LogInfo should be defined like
the following. Notice how one set of parentheses are removed because X
already contains a set of parentheses.

#define LogInfo( X ) printf X

Thank you for providing a concise version of the README.

aggarg · 2021-02-06T23:11:54Z

libraries/logging/include/logging_stack.h

+ * @note By default, this configuration is disabled by
+ */
+#ifndef LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION
+    #define LOGGING_ENABLE_METADATA_WITH_C99_AND_GNU_EXTENSION    0


Reading the README I got the impression that the default is 1.

Nope, will make it clear in the README

aggarg · 2021-02-06T23:17:10Z

libraries/logging/iot_logging_task_dynamic_buffers.c

+        /* Add the chosen log level information as prefix for the message. */
+        if( pcLevelString != NULL )
+        {
+            xLength += snprintf( pcPrintString + xLength, configLOGGING_MAX_MESSAGE_LENGTH - xLength, "[%s] ", pcLevelString );


Should we check snprintf failure?

Added an assert as negative value is returned by snprintf only for encoding errors.

libraries/logging/iot_logging_task_dynamic_buffers.c

aggarw13 · 2021-02-08T19:31:21Z

/bot run checks

libraries/logging/README.md

Co-authored-by: Gaurav-Aggarwal-AWS <33462878+aggarg@users.noreply.github.com>

aggarw13 added 4 commits January 25, 2021 22:31

Attempt to remove task name and time metadata duplication in logs

229c340

Fix build issue

b2108d9

Fix bug in modified logic

d201319

doc: add some comments for modified logic

059df8f

aggarw13 requested a review from a team as a code owner January 26, 2021 01:03

aggarw13 changed the title ~~Remove duplication of metadata from log messages~~ Remove repetition of metadata in log messages Jan 26, 2021

leegeth reviewed Jan 26, 2021

View reviewed changes

libraries/logging/iot_logging_task_dynamic_buffers.c Outdated Show resolved Hide resolved

aggarw13 added 7 commits January 27, 2021 02:17

test assembling string before logging messsage

2293563

Fix build issues

a644c0f

Make __LINE__ value resolution accurate by removing formatting from S…

9eb99d1

…dkAssembleAndLog macro

Replace overflow assert with logic to end buffer with line endings

3662a78

Merge branch 'poc/logging-thread-safety-issue' of github.com:aggarw13…

54d2d44

…/amazon-freertos into poc/logging-thread-safety-issue

Fix overflow handling logic

85848e9

avoid double copy operation in messages through LogXXX macros

2548f9e

aggarw13 added 11 commits January 27, 2021 17:31

Fix logic of updating state of newLogMessage flag

8a25224

Remove code comminization in previous commit as string needs to be co…

2874ecb

…pied for enqueing and processing in logging task

Add support for Keil compiler

c14785a

Refactor logging_stack.h to provide C99 and C89 compatible implementa…

ddca1e5

…tions

Add a README for the logging library

5e86313

Update vLoggingPrintf implementation to add newline characters

47d6ffa

FIx incorrect usage of snprintf when adding newling characters

d46422d

Fix build issue

7cd8530

Fix issue of undefined SdkLog

46e7110

Remove extra space ERROR log messages

294b084

Attempt to fix Windows build issues

995c32c

Attempt to fix build failures for Microchip

809e490

leegeth reviewed Feb 4, 2021

View reviewed changes

libraries/logging/README.md Outdated Show resolved Hide resolved

leegeth reviewed Feb 4, 2021

View reviewed changes

libraries/logging/README.md Outdated Show resolved Hide resolved

leegeth reviewed Feb 4, 2021

View reviewed changes

libraries/logging/iot_logging_task_dynamic_buffers.c Show resolved Hide resolved

aggarw13 added 2 commits February 4, 2021 21:41

Improvements in README

006b35f

Remove xEndofMessage static variable

1495715

leegeth previously approved these changes Feb 4, 2021

View reviewed changes

aggarw13 dismissed leegeth’s stale review via 95d0028 February 4, 2021 22:53

aggarw13 added 2 commits February 4, 2021 22:54

Fixes in Windows implementations

c98a928

Hygiene changes in logging task files

95d0028

leegeth previously approved these changes Feb 4, 2021

View reviewed changes

aggarg reviewed Feb 6, 2021

View reviewed changes

aggarw13 dismissed leegeth’s stale review via f6d3537 February 7, 2021 02:36

aggarw13 added 2 commits February 7, 2021 02:37

Minor changes from review comments

f6d3537

Improve README

6512188

aggarg reviewed Feb 8, 2021

View reviewed changes

libraries/logging/README.md Outdated Show resolved Hide resolved

libraries/logging/README.md Outdated Show resolved Hide resolved

libraries/logging/README.md Outdated Show resolved Hide resolved

Minor fixes in README

de73cfc

Co-authored-by: Gaurav-Aggarwal-AWS <33462878+aggarg@users.noreply.github.com>

aggarg approved these changes Feb 8, 2021

View reviewed changes

aggarw13 merged commit 0cd9580 into aws:master Feb 8, 2021

aggarw13 deleted the fix/logging-metadata-duplicate-issue branch February 8, 2021 21:53

This was referenced Feb 9, 2021

Logging issues #2952

Closed

Add updates about test runner and ESP-IDF in CHANGELOG #2970

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Remove repetition of metadata in log messages #2953

Remove repetition of metadata in log messages #2953

aggarw13 commented Jan 26, 2021 •

edited

Loading

nateglims commented Jan 27, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

leegeth Feb 4, 2021

aggarg Feb 6, 2021

aggarw13 Feb 8, 2021

aggarg Feb 6, 2021

aggarw13 Feb 8, 2021

aggarg Feb 6, 2021

aggarw13 Feb 8, 2021

aggarg Feb 6, 2021

aggarw13 Feb 7, 2021

aggarw13 commented Feb 8, 2021

		@@ -0,0 +1,109 @@
		## Sample Implementation of Logging Interface

		This library provides reference implementations of the [logging interface](#the-logging-interface) that is used by FreeRTOS libraries and demos to generate log messages. This library provides

Remove repetition of metadata in log messages #2953

Remove repetition of metadata in log messages #2953

Conversation

aggarw13 commented Jan 26, 2021 • edited Loading

Problem

Problem 1: Metadata is duplicated in log messages

Problem 2: Log messages are out-of-order when LogXXXX macros are called in multi-threaded environment

Solution

nateglims commented Jan 27, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

nateglims commented Jan 28, 2021

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

Sample Implementation of Logging Interface

Using your custom implementation of Logging Interface

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

aggarw13 commented Feb 8, 2021

aggarw13 commented Jan 26, 2021 •

edited

Loading

Problem 2: Log messages are out-of-order when `LogXXXX` macros are called in multi-threaded environment