[FL-1147] System logging (#434)

* furi_log: introduce log system
* applications: rework with furi logging
* furi_log: reset color after tag printed
* core: add log info

Co-authored-by: あく <alleteam@gmail.com>

applications/app-loader/app-loader.c

@@ -58,6 +58,7 @@ void app_loader_thread_state_callback(FuriThreadState state, void* context) {
 }
 
 int32_t app_loader(void* p) {
+    FURI_LOG_I("APPLOADER", "Started");
     state.thread = furi_thread_alloc();
     furi_thread_set_state_context(state.thread, &state);
     furi_thread_set_state_callback(state.thread, app_loader_thread_state_callback);
@@ -153,7 +154,7 @@ int32_t app_loader(void* p) {
             menu_item_add(menu, menu_debug);
         });
 
-    printf("[app loader] start\r\n");
+    FURI_LOG_I("APPLOADER", "OK");
 
     while(1) {
         osThreadSuspend(osThreadGetId());

applications/examples/input_dump.c

@@ -72,14 +72,15 @@ int32_t application_input_dump(void* p) {
     Gui* gui = furi_record_open("gui");
     gui_add_view_port(gui, view_port, GuiLayerFullscreen);
 
-    printf("[input_dump] waiting for input events\r\n");
+    FURI_LOG_I("INPUT DUMP", "waiting for input events");
     InputDumpEvent event;
 
     while(1) {
         furi_check(osMessageQueueGet(event_queue, &event, NULL, osWaitForever) == osOK);
 
-        printf(
+        FURI_LOG_I(
-            "[input_dump] key: %s type: %s\r\n",
+            "INPUT DUMP",
+            "key: %s type: %s",
             input_dump_get_key_name(event.input.key),
             input_dump_get_type_name(event.input.type));
 
@@ -88,7 +89,7 @@ int32_t application_input_dump(void* p) {
         }
     }
 
-    printf("[input_dump] shutting down, byebye!\r\n");
+    FURI_LOG_I("INPUT DUMP", "shutting down, byebye!");
 
     view_port_enabled_set(view_port, false);
     gui_remove_view_port(gui, view_port);

applications/sd-filesystem/sd-filesystem.c

@@ -282,8 +282,9 @@ bool app_sd_mount_card(SdApp* sd_app) {
 
         if(!result) {
             delay(1000);
-            printf(
+            FURI_LOG_E(
-                "[sd_filesystem] init(%d), error: %s\r\n",
+                "SD FILESYSTEM",
+                "init(%d), error: %s\r\n",
                 counter,
                 fs_error_get_internal_desc(sd_app->info.status));
 
@@ -613,7 +614,7 @@ int32_t sd_filesystem(void* p) {
     with_value_mutex(
         menu_vm, (Menu * menu) { menu_item_add(menu, menu_item); });
 
-    printf("[sd_filesystem] start\r\n");
+    FURI_LOG_I("SD FILESYSTEM", "start");
 
     // add api record
     furi_record_create("sdcard", fs_api);
@@ -628,16 +629,17 @@ int32_t sd_filesystem(void* p) {
     while(true) {
         if(sd_was_present) {
             if(hal_sd_detect()) {
-                printf("[sd_filesystem] card detected\r\n");
+                FURI_LOG_I("SD FILESYSTEM", "Card detected");
                 app_sd_mount_card(sd_app);
 
                 if(sd_app->info.status != SD_OK) {
-                    printf(
+                    FURI_LOG_E(
-                        "[sd_filesystem] sd init error: %s\r\n",
+                        "SD FILESYSTEM",
+                        "sd init error: %s",
                         fs_error_get_internal_desc(sd_app->info.status));
                     app_sd_notify_error();
                 } else {
-                    printf("[sd_filesystem] sd init ok\r\n");
+                    FURI_LOG_I("SD FILESYSTEM", "sd init ok");
                     app_sd_notify_success();
                 }
 
@@ -645,7 +647,7 @@ int32_t sd_filesystem(void* p) {
                 sd_was_present = false;
 
                 if(!hal_sd_detect()) {
-                    printf("[sd_filesystem] card removed\r\n");
+                    FURI_LOG_I("SD FILESYSTEM", "card removed");
 
                     view_port_enabled_set(sd_app->icon.view_port, false);
                     app_sd_unmount_card(sd_app);
@@ -654,7 +656,7 @@ int32_t sd_filesystem(void* p) {
             }
         } else {
             if(!hal_sd_detect()) {
-                printf("[sd_filesystem] card removed\r\n");
+                FURI_LOG_I("SD FILESYSTEM", "card removed");
 
                 view_port_enabled_set(sd_app->icon.view_port, false);
                 app_sd_unmount_card(sd_app);

core/flipper.c

@@ -4,17 +4,22 @@
 #include <version.h>
 #include <api-hal-version.h>
 
-static void flipper_print_version(const Version* version) {
+static void flipper_print_version(const char* target, const Version* version) {
     if(version) {
-        printf("\tVersion:\t%s\r\n", version_get_version(version));
+        FURI_LOG_I(
-        printf("\tBuild date:\t%s\r\n", version_get_builddate(version));
+            "FLIPPER",
-        printf(
+            "\r\n\t%s version:\t%s\r\n"
-            "\tGit Commit:\t%s (%s)\r\n",
+            "\tBuild date:\t\t%s\r\n"
+            "\tGit Commit:\t\t%s (%s)\r\n"
+            "\tGit Branch:\t\t%s",
+            target,
+            version_get_version(version),
+            version_get_builddate(version),
             version_get_githash(version),
-            version_get_gitbranchnum(version));
+            version_get_gitbranchnum(version),
-        printf("\tGit Branch:\t%s\r\n", version_get_gitbranch(version));
+            version_get_gitbranch(version));
     } else {
-        printf("\tNo build info\r\n");
+        FURI_LOG_I("FLIPPER", "No build info for %s", target);
     }
 }
 
@@ -22,17 +27,15 @@ void flipper_init() {
     const Version* version;
 
     version = (const Version*)api_hal_version_get_boot_version();
-    printf("Bootloader\r\n");
+    flipper_print_version("Bootloader", version);
-    flipper_print_version(version);
 
     version = (const Version*)api_hal_version_get_fw_version();
-    printf("Firmware\r\n");
+    flipper_print_version("Firmware", version);
-    flipper_print_version(version);
 
-    printf("[flipper] starting services\r\n");
+    FURI_LOG_I("FLIPPER", "starting services");
 
     for(size_t i = 0; i < FLIPPER_SERVICES_COUNT; i++) {
-        printf("[flipper] starting service %s\r\n", FLIPPER_SERVICES[i].name);
+        FURI_LOG_I("FLIPPER", "starting service %s", FLIPPER_SERVICES[i].name);
 
         FuriThread* thread = furi_thread_alloc();
 
@@ -43,5 +46,5 @@ void flipper_init() {
         furi_thread_start(thread);
     }
 
-    printf("[flipper] services startup complete\r\n");
+    FURI_LOG_I("FLIPPER", "services startup complete");
 }

core/furi.c

@@ -2,6 +2,7 @@
 
 void furi_init() {
     api_interrupt_init();
+    furi_log_init();
     furi_record_init();
     furi_stdglue_init();
 }

core/furi.h

@@ -9,6 +9,7 @@
 #include <furi/stdglue.h>
 #include <furi/thread.h>
 #include <furi/valuemutex.h>
+#include <furi/log.h>
 
 #include <api-hal-gpio.h>
 #include <api-hal/api-interrupt-mgr.h>

core/furi/log.c

@@ -0,0 +1,52 @@
+#include "log.h"
+#include <stm32wbxx_hal.h>
+#include "check.h"
+
+typedef struct {
+    FuriLogLevel log_level;
+    FuriLogPrint print;
+    FuriLogVPrint vprint;
+    FuriLogTimestamp timetamp;
+} FuriLogParams;
+
+static FuriLogParams furi_log;
+
+void furi_log_init() {
+    // Set default logging parameters
+    furi_log.log_level = FURI_LOG_LEVEL;
+    furi_log.print = printf;
+    furi_log.vprint = vprintf;
+    furi_log.timetamp = HAL_GetTick;
+}
+
+void furi_log_print(FuriLogLevel level, const char* format, ...) {
+    va_list args;
+    va_start(args, format);
+    if(level <= furi_log.log_level) {
+        furi_log.print("%lu ", furi_log.timetamp());
+        furi_log.vprint(format, args);
+    }
+    va_end(args);
+}
+
+void furi_log_set_level(FuriLogLevel level) {
+    furi_log.log_level = level;
+}
+
+FuriLogLevel furi_log_get_level(void) {
+    return furi_log.log_level;
+}
+
+void furi_log_set_print(FuriLogPrint print, FuriLogVPrint vprint) {
+    furi_assert(print);
+    furi_assert(vprint);
+
+    furi_log.print = print;
+    furi_log.vprint = vprint;
+}
+
+void furi_log_set_timestamp(FuriLogTimestamp timestamp) {
+    furi_assert(timestamp);
+
+    furi_log.timetamp = timestamp;
+}

core/furi/log.h

@@ -0,0 +1,66 @@
+#pragma once
+
+#include <stdio.h>
+#include <stdint.h>
+#include <stdarg.h>
+
+#ifdef __cplusplus
+extern "C" {
+#endif
+
+#define FURI_LOG_LEVEL_DEFAULT 3
+
+#ifndef FURI_LOG_LEVEL
+#define FURI_LOG_LEVEL FURI_LOG_LEVEL_DEFAULT
+#endif
+
+#define FURI_LOG_CLR(clr) "\033[0;" clr "m"
+#define FURI_LOG_CLR_RESET "\033[0m"
+
+#define FURI_LOG_CLR_BLACK "30"
+#define FURI_LOG_CLR_RED "31"
+#define FURI_LOG_CLR_GREEN "32"
+#define FURI_LOG_CLR_BROWN "33"
+#define FURI_LOG_CLR_BLUE "34"
+#define FURI_LOG_CLR_PURPLE "35"
+
+#define FURI_LOG_CLR_E FURI_LOG_CLR(FURI_LOG_CLR_RED)
+#define FURI_LOG_CLR_W FURI_LOG_CLR(FURI_LOG_CLR_BROWN)
+#define FURI_LOG_CLR_I FURI_LOG_CLR(FURI_LOG_CLR_GREEN)
+#define FURI_LOG_CLR_D FURI_LOG_CLR(FURI_LOG_CLR_BLUE)
+#define FURI_LOG_CLR_V
+
+typedef int (*FuriLogPrint)(const char*, ...);
+typedef int (*FuriLogVPrint)(const char*, va_list);
+typedef uint32_t (*FuriLogTimestamp)(void);
+
+typedef enum {
+    FURI_LOG_NONE = 0,
+    FURI_LOG_ERROR = 1,
+    FURI_LOG_WARN = 2,
+    FURI_LOG_INFO = 3,
+    FURI_LOG_DEBUG = 4,
+    FURI_LOG_VERBOSE = 5,
+} FuriLogLevel;
+
+void furi_log_init();
+void furi_log_print(FuriLogLevel level, const char* format, ...);
+void furi_log_set_level(FuriLogLevel level);
+FuriLogLevel furi_log_get_level();
+void furi_log_set_print(FuriLogPrint print, FuriLogVPrint vprint);
+void furi_log_set_timestamp(FuriLogTimestamp timestamp);
+
+#define FURI_LOG_FORMAT(log_letter, tag, format) \
+    FURI_LOG_CLR_##log_letter "[" #log_letter "][" tag "]: " FURI_LOG_CLR_RESET format "\r\n"
+#define FURI_LOG_SHOW(tag, format, log_level, log_letter, ...) \
+    furi_log_print(log_level, FURI_LOG_FORMAT(log_letter, tag, format), ##__VA_ARGS__)
+
+#define FURI_LOG_E(tag, format, ...) FURI_LOG_SHOW(tag, format, FURI_LOG_ERROR, E, ##__VA_ARGS__)
+#define FURI_LOG_W(tag, format, ...) FURI_LOG_SHOW(tag, format, FURI_LOG_WARN, W, ##__VA_ARGS__)
+#define FURI_LOG_I(tag, format, ...) FURI_LOG_SHOW(tag, format, FURI_LOG_INFO, I, ##__VA_ARGS__)
+#define FURI_LOG_D(tag, format, ...) FURI_LOG_SHOW(tag, format, FURI_LOG_DEBUG, D, ##__VA_ARGS__)
+#define FURI_LOG_V(tag, format, ...) FURI_LOG_SHOW(tag, format, FURI_LOG_VERBOSE, V, ##__VA_ARGS__)
+
+#ifdef __cplusplus
+}
+#endif

firmware/targets/f5/Src/main.c

@@ -30,32 +30,50 @@ int main(void) {
     // Initialize ST HAL hardware
     HAL_Init();
     SystemClock_Config();
-    MX_GPIO_Init();
-    MX_ADC1_Init();
-    MX_RTC_Init();
-    MX_SPI1_Init();
-    MX_SPI2_Init();
     MX_USART1_UART_Init();
+    FURI_LOG_I("HAL", "USART OK");
+    MX_RTC_Init();
+    FURI_LOG_I("HAL", "RTC OK");
+    MX_GPIO_Init();
+    FURI_LOG_I("HAL", "GPIO OK");
+    MX_ADC1_Init();
+    FURI_LOG_I("HAL", "ADC1 OK");
+    MX_SPI1_Init();
+    FURI_LOG_I("HAL", "SPI1 OK");
+    MX_SPI2_Init();
+    FURI_LOG_I("HAL", "SPI2 OK");
     MX_USB_Device_Init();
+    FURI_LOG_I("HAL", "USB OK");
     MX_TIM1_Init();
+    FURI_LOG_I("HAL", "TIM1 OK");
     MX_TIM2_Init();
+    FURI_LOG_I("HAL", "TIM2 OK");
     MX_TIM16_Init();
+    FURI_LOG_I("HAL", "TIM16 OK");
     MX_COMP1_Init();
+    FURI_LOG_I("HAL", "COMP1 OK");
     MX_RF_Init();
+    FURI_LOG_I("HAL", "RF OK");
     MX_PKA_Init();
+    FURI_LOG_I("HAL", "PKA OK");
     MX_RNG_Init();
+    FURI_LOG_I("HAL", "RNG OK");
     MX_AES1_Init();
+    FURI_LOG_I("HAL", "AES1 OK");
     MX_AES2_Init();
+    FURI_LOG_I("HAL", "AES2 OK");
     MX_CRC_Init();
+    FURI_LOG_I("HAL", "CRC OK");
 
     // Flipper API HAL
     api_hal_init();
 
     // 3rd party
     MX_FATFS_Init();
-
+    FURI_LOG_I("HAL", "FATFS OK");
     // CMSIS initialization
     osKernelInitialize();
+    FURI_LOG_I("HAL", "KERNEL OK");
     // Init flipper
     flipper_init();
     // Start kernel

firmware/targets/f5/api-hal/api-hal.c

@@ -2,12 +2,21 @@
 
 void api_hal_init() {
     api_hal_delay_init();
+    FURI_LOG_I("FURI_HAL", "DELAY OK");
     api_hal_os_init();
+    FURI_LOG_I("FURI_HAL", "OS OK");
     api_hal_vcp_init();
+    FURI_LOG_I("FURI_HAL", "VCP OK");
     api_hal_spi_init();
+    FURI_LOG_I("FURI_HAL", "SPI OK");
     api_hal_i2c_init();
+    FURI_LOG_I("FURI_HAL", "I2C OK");
     api_hal_power_init();
+    FURI_LOG_I("FURI_HAL", "POWER OK");
     api_hal_light_init();
+    FURI_LOG_I("FURI_HAL", "LIGHT OK");
     api_hal_vibro_init();
+    FURI_LOG_I("FURI_HAL", "VIBRO OK");
     api_hal_subghz_init();
+    FURI_LOG_I("FURI_HAL", "SUBGHZ OK");
 }