Improved logging on stm32 platform

Introduces configureable logging with maximum log level, optional colorization by level, and optional source file and line numers with log messages (always on for `ERROR` messages), as described in stm32 section of `Build Instructions`. Signed-off-by: Winford <[email protected]>
atomvm · Aug 28, 2023 · 6062b0a · 6062b0a
1 parent 42cc656
commit 6062b0a
Show file tree

Hide file tree

Showing 7 changed files with 200 additions and 16 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -6,6 +6,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [0.6.0-alpha.1] - Unreleased
 
+### Added
+
+- Added configurable logging macros to stm32 platform
+
 ### Fixed
 
 - Fixed `esp:nvs_set_binary` functions.

diff --git a/doc/src/build-instructions.md b/doc/src/build-instructions.md
@@ -528,8 +528,22 @@ If you are building for a different target board the `CLOCK_FREQUENCY` definitio
 
 The rcc_clock_setup_XXX_XXX will also need to be changed to match your particular chip-set. Consult [ST's documentation](https://www.st.com/en/microcontrollers-microprocessors/stm32-32-bit-arm-cortex-mcus.html) for appropriate settings.
 
+### Configure logging with `cmake`
+The default maximum log level is `LOG_INFO`. To change the maximum level displayed pass `-DAVM_LOG_LEVEL_MAX="{level}"` to `cmake`, with one of `LOG_ERROR`, `LOG_WARN`, `LOG_INFO`, or `LOG_DEBUG` (listed from least to most verbose). Log messages can be completely disabled by using `-DAVM_LOG_DISABLE=on`.
+
+For log entries colorized by log level pass `-DAVM_ENABLE_LOG_COLOR=on` to cmake. With color enable there is a very small performance penalty (~1ms per message printed), the log entries are colored as follows:
+
+| Message Level |  Color  |
+|---------------|---------|
+| ERROR | Red |
+| WARN | Orange |
+| INFO | Green |
+| DEBUG | Blue |
+
+By default only `ERROR` messages contain file and line number information. This can be included with all log entries by passing `-DAVM_ENABLE_LOG_LINES=on` to cmake, but it does incur a significant performance penalty and is only suggested for debugging during development.
+
 ### Printing
-AtomVM is built with standard `newlib` to support `long long` integers (`signed` and `unsigned`). If you are building for a device with extremely limited flash space the `nano` version of `newlib` can be used instead. This will save approximately 46kB of flash. This may be done by passing `-DAVM_NEWLIB_NANO=on`.
+AtomVM is built with standard `newlib` to support `long long` integers (`signed` and `unsigned`). If you are building for a device with extremely limited flash space the `nano` version of `newlib` can be used instead. This may be done by passing `-DAVM_NEWLIB_NANO=on`. If the `nano newlib` is used logs will be automatically disabled, this is because many of the VM low level log messages will include `%ull` formatting and will cause buffer overflows and crash the VM if logging is not disabled for `nano newlib` builds. The total flash savings of using `nano newlib` and disabling logs is just under 40kB.
 
 By default, stdout and stderr are printed on USART2. On the STM32F4Discovery board, you can see them
 using a TTL-USB with the TX pin connected to board's pin PA2 (USART2 RX). Baudrate is 115200 and serial transmission

diff --git a/src/platforms/stm32/CMakeLists.txt b/src/platforms/stm32/CMakeLists.txt
@@ -20,20 +20,43 @@
 
 cmake_minimum_required (VERSION 3.13)
 project(AtomVM)
+
 list(APPEND CMAKE_MODULE_PATH "${CMAKE_CURRENT_SOURCE_DIR}/../../../CMakeModules")
 set(CMAKE_RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR})
 
-
 # Options that make sense for this platform
 option(AVM_USE_32BIT_FLOAT "Use 32 bit floats." OFF)
 option(AVM_VERBOSE_ABORT "Print module and line number on VM abort" OFF)
 option(AVM_CREATE_STACKTRACES "Create stacktraces" ON)
 option(AVM_NEWLIB_NANO "Use 'nano' newlib. Saves 46kB, no `long long` support" OFF)
+option(AVM_LOG_DISABLE "Disable log output" OFF)
+option(AVM_ENABLE_LOG_COLOR "Use color log output" OFF)
+option(AVM_ENABLE_LOG_LINES "Include source and line info for all enbled levels" OFF)
 
 set(AVM_DISABLE_SMP ON FORCE)
 
 if (AVM_NEWLIB_NANO)
     set(LINKER_FLAGS "${LINKER_FLAGS} -specs=nano.specs")
+    set(AVM_LOG_DISABLE ON FORCE)
+endif()
+
+# Configure logging
+if (AVM_LOG_DISABLE)
+    add_compile_definitions(AVM_LOG_DISABLE)
+elseif (AVM_LOG_LEVEL_MAX)
+    set(CONFIG_LOG_LEVEL_MAX ${AVM_LOG_LEVEL_MAX} CACHE STRING "AtomVM max log level")
+else()
+    set(CONFIG_LOG_LEVEL_MAX LOG_INFO CACHE STRING "AtomVM max log level")
+endif()
+if (CONFIG_LOG_LEVEL_MAX)
+    set_property(CACHE CONFIG_LOG_LEVEL_MAX PROPERTY STRINGS LOG_NONE LOG_ERROR LOG_WARN LOG_INFO LOG_DEBUG)
+    add_compile_definitions(CONFIG_LOG_LEVEL_MAX=${CONFIG_LOG_LEVEL_MAX})
+endif()
+if (AVM_ENABLE_LOG_COLOR)
+    add_compile_definitions(ENABLE_LOG_COLOR)
+endif()
+if (AVM_ENABLE_LOG_LINES)
+    add_compile_definitions(ENABLE_LOG_LINE_INFO)
 endif()
 
 # Include an error in case the user forgets to specify ARM as a toolchain

diff --git a/src/platforms/stm32/src/lib/CMakeLists.txt b/src/platforms/stm32/src/lib/CMakeLists.txt
@@ -24,6 +24,8 @@ project (libAtomVMPlatformSTM32)
 set(HEADER_FILES
     gpiodriver.h
     platform_defaultatoms.h
+    avm_log.h
+    ../../../../libAtomVM/sys.h
 )
 
 set(SOURCE_FILES

diff --git a/src/platforms/stm32/src/lib/avm_log.h b/src/platforms/stm32/src/lib/avm_log.h
@@ -0,0 +1,112 @@
+/* This file is part of AtomVM.
+ *
+ * Copyright 2023 Winford (Uncle Grumpy) <[email protected]>
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *    http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0 OR LGPL-2.1-or-later
+ */
+
+#ifndef _AVM_LOG_H_
+#define _AVM_LOG_H_
+
+#include <stdint.h>
+#include <stdio.h>
+
+#include <sys.h>
+
+enum AVMLogLevel
+{
+    LOG_NONE = 0,
+    LOG_ERROR,
+    LOG_WARN,
+    LOG_INFO,
+    LOG_DEBUG
+};
+
+#ifndef AVM_LOG_DISABLE
+
+#ifdef CONFIG_LOG_LEVEL_MAX
+#define LOG_LEVEL_MAX CONFIG_LOG_LEVEL_MAX
+#else
+#define LOG_LEVEL_MAX LOG_INFO
+#endif
+
+/* clang-format off */
+#ifdef ENABLE_LOG_COLOR
+// #define LOG_COLOR_BLACK   "\033[0;30m"
+// #define LOG_COLOR_GREY    "\033[1;30m"
+// #define LOG_COLOR_RED     "\033[0;31m"
+// #define LOG_BOLD_RED      "\033[1;31m"
+// #define LOG_COLOR_GREEN   "\033[0;32m"
+// #define LOG_COLOR_ALIEN   "\033[1;32m"
+// #define LOG_COLOR_ORANGE  "\033[0;33m"
+// #define LOG_COLOR_YELLOW  "\033[1;33m"
+// #define LOG_COLOR_BLUE    "\033[0;34m"
+// #define LOG_COLOR_PURPLE  "\033[0;35m"
+// #define LOG_COLOR_PINK    "\033[1;35m"
+// #define LOG_COLOR_CYAN    "\033[0;36m"
+#define LOG_COLOR_ERROR   "\033[1;31m"
+#define LOG_COLOR_WARN    "\033[0;33m"
+#define LOG_COLOR_INFO    "\033[0;32m"
+#define LOG_COLOR_DEBUG   "\033[0;34m"
+#define LOG_RESET_COLOR   "\033[0m"
+#else /* ENABLE_LOG_COLOR OFF */
+#define LOG_COLOR_ERROR
+#define LOG_COLOR_WARN
+#define LOG_COLOR_INFO
+#define LOG_COLOR_DEBUG
+#define LOG_RESET_COLOR
+#endif /* ENABLE_LOG_COLOR */
+
+#ifdef ENABLE_LOG_LINE_INFO
+#define LINE_FORMAT " (%s:%i)"
+#define LINE_DATA   , __FILE__, __LINE__
+#else /* ENABLE_LOG_LINE_INFO OFF*/
+#define LINE_FORMAT
+#define LINE_DATA
+#endif /* ENABLE_LOG_LINE_INFO */
+/* clang-format on */
+
+#define AVM_LOGE(tag, format, ...)                                                                                                               \
+    do {                                                                                                                                         \
+        uint64_t logtime = sys_monotonic_millis();                                                                                               \
+        if (LOG_LEVEL_MAX >= LOG_ERROR)                                                                                                          \
+            printf(LOG_COLOR_ERROR "ERROR [%llu] %s: " format " (%s:%i)" LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__, __FILE__, __LINE__); \
+    } while (0)
+#define AVM_LOGW(tag, format, ...)                                                                                                    \
+    do {                                                                                                                              \
+        uint64_t logtime = sys_monotonic_millis();                                                                                    \
+        if (LOG_LEVEL_MAX >= LOG_WARN)                                                                                                \
+            printf(LOG_COLOR_WARN "WARN [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
+    } while (0)
+#define AVM_LOGI(tag, format, ...)                                                                                                    \
+    do {                                                                                                                              \
+        uint64_t logtime = sys_monotonic_millis();                                                                                    \
+        if (LOG_LEVEL_MAX >= LOG_INFO)                                                                                                \
+            printf(LOG_COLOR_INFO "INFO [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
+    } while (0)
+#define AVM_LOGD(tag, format, ...)                                                                                                      \
+    do {                                                                                                                                \
+        uint64_t logtime = sys_monotonic_millis();                                                                                      \
+        if (LOG_LEVEL_MAX >= LOG_DEBUG)                                                                                                 \
+            printf(LOG_COLOR_DEBUG "DEBUG [%llu] %s: " format LINE_FORMAT LOG_RESET_COLOR "\n", logtime, tag, ##__VA_ARGS__ LINE_DATA); \
+    } while (0)
+#else
+#define AVM_LOGE(tag, format, ...)
+#define AVM_LOGW(tag, format, ...)
+#define AVM_LOGI(tag, format, ...)
+#define AVM_LOGD(tag, format, ...)
+#endif /* AVM_LOG_DISABLE */
+
+#endif /* _AVM_LOG_H_ */
diff --git a/src/platforms/stm32/src/lib/sys.c b/src/platforms/stm32/src/lib/sys.c
@@ -18,15 +18,17 @@
  * SPDX-License-Identifier: Apache-2.0 OR LGPL-2.1-or-later
  */
 
-#include <sys.h>
-
 #include <avmpack.h>
 #include <defaultatoms.h>
 #include <scheduler.h>
+#include <sys.h>
+
+#include <trace.h>
 
+#include "avm_log.h"
 #include "gpiodriver.h"
 
-#include "trace.h"
+#define TAG "sys"
 
 void sys_tick_handler();
 
@@ -107,6 +109,7 @@ enum OpenAVMResult sys_open_avm_from_file(
     TRACE("sys_open_avm_from_file: Going to open: %s\n", path);
 
     // TODO
+    AVM_LOGW(TAG, "Open from file not supported on this platform.");
     return AVM_OPEN_NOT_SUPPORTED;
 }
 
@@ -133,7 +136,7 @@ Module *sys_load_module(GlobalContext *global, const char *module_name)
     synclist_unlock(&global->avmpack_data);
 
     if (IS_NULL_PTR(beam_module)) {
-        fprintf(stderr, "Failed to open module: %s\n", module_name);
+        AVM_LOGE(TAG, "Failed to open module: %s.", module_name);
         return NULL;
     }
 

diff --git a/src/platforms/stm32/src/main.c b/src/platforms/stm32/src/main.c
@@ -19,24 +19,46 @@
  */
 
 #include <errno.h>
+#include <stdio.h>
+#include <unistd.h>
+
 #include <libopencm3/cm3/nvic.h>
 #include <libopencm3/cm3/systick.h>
 #include <libopencm3/stm32/gpio.h>
 #include <libopencm3/stm32/rcc.h>
 #include <libopencm3/stm32/usart.h>
-#include <stdio.h>
-#include <unistd.h>
 
 #include <avmpack.h>
 #include <context.h>
 #include <globalcontext.h>
 #include <module.h>
+#include <utils.h>
+#include <version.h>
+
+#include "lib/avm_log.h"
 
 #define USART_CONSOLE USART2
 #define AVM_ADDRESS (0x8080000)
 #define AVM_FLASH_MAX_SIZE (0x80000)
 #define CLOCK_FREQUENCY (168000000)
 
+#define TAG "AtomVM"
+
+#define ATOMVM_BANNER                                                   \
+    "\n"                                                                \
+    "    ###########################################################\n" \
+    "\n"                                                                \
+    "       ###    ########  #######  ##     ## ##     ## ##     ## \n" \
+    "      ## ##      ##    ##     ## ###   ### ##     ## ###   ### \n" \
+    "     ##   ##     ##    ##     ## #### #### ##     ## #### #### \n" \
+    "    ##     ##    ##    ##     ## ## ### ## ##     ## ## ### ## \n" \
+    "    #########    ##    ##     ## ##     ##  ##   ##  ##     ## \n" \
+    "    ##     ##    ##    ##     ## ##     ##   ## ##   ##     ## \n" \
+    "    ##     ##    ##     #######  ##     ##    ###    ##     ## \n" \
+    "\n"                                                                \
+    "    ###########################################################\n" \
+    "\n"
+
 int _write(int file, char *ptr, int len);
 
 static void clock_setup()
@@ -106,26 +128,31 @@ int main()
     systick_setup();
     usart_setup();
 
+    fprintf(stdout, "%s", ATOMVM_BANNER);
+    AVM_LOGI(TAG, "Starting AtomVM revision " ATOMVM_VERSION);
+    AVM_LOGD(TAG, "Using usart mapped at register 0x%x for stdout/stderr.", USART_CONSOLE);
+
     const void *flashed_avm = (void *) AVM_ADDRESS;
     uint32_t size = AVM_FLASH_MAX_SIZE;
 
     uint32_t startup_beam_size;
     const void *startup_beam;
     const char *startup_module_name;
 
-    printf("Booting file mapped at: %p, size: %li\n", flashed_avm, size);
+    AVM_LOGD(TAG, "Maximum application size: %lu", size);
 
     GlobalContext *glb = globalcontext_new();
 
     if (!avmpack_is_valid(flashed_avm, size) || !avmpack_find_section_by_flag(flashed_avm, BEAM_START_FLAG, &startup_beam, &startup_beam_size, &startup_module_name)) {
-        fprintf(stderr, "error: invalid AVM Pack\n");
-        return 1;
+        AVM_LOGE(TAG, "Invalid AVM Pack");
+        AVM_ABORT();
     }
+    AVM_LOGI(TAG, "Booting file mapped at: %p, size: %lu", flashed_avm, startup_beam_size);
 
     struct ConstAVMPack *avmpack_data = malloc(sizeof(struct ConstAVMPack));
     if (IS_NULL_PTR(avmpack_data)) {
-        fprintf(stderr, "Memory error: Cannot allocate AVMPackData.\n");
-        return 1;
+        AVM_LOGE(TAG, "Memory error: Cannot allocate AVMPackData.");
+        AVM_ABORT();
     }
     avmpack_data_init(&avmpack_data->base, &const_avm_pack_info);
     avmpack_data->base.data = flashed_avm;
@@ -136,10 +163,9 @@ int main()
     globalcontext_insert_module(glb, mod);
     Context *ctx = context_new(glb);
 
-    printf("Starting: %s...\n", startup_module_name);
-    printf("---\n");
+    AVM_LOGI(TAG, "Starting: %s...\n", startup_module_name);
     context_execute_loop(ctx, mod, "start", 0);
-    printf("Return value: %lx\n", (long) term_to_int32(ctx->x[0]));
+    AVM_LOGI(TAG, "Return value: %lx", (long) term_to_int32(ctx->x[0]));
 
     while (1)
         ;