[ulog][rtc][time][bug] solve the interference when enable the ulog timestamp (#5687)

* [ulog] 解决ulog开启时间戳后与libc time以及rtc驱动相关函数干涉的问题
* ulog：当发生递归输出时，后续递归想要输出的内容可能会因为防范递归的判断而无法输出
因此修改输出规则，在发生递归时，采用简单的，无格式的方式直接输出。这样既保证不会发生递归输出，也可以保证递归输出的部分可以正常输出。
* [ulog] size_t->rt_size_t NULL->RT_NULL

bsp/stm32/libraries/HAL_Drivers/drv_rtc.c

@@ -249,7 +249,7 @@ static rt_err_t stm32_rtc_get_secs(void *args)
     struct timeval tv;
     get_rtc_timeval(&tv);
     *(rt_uint32_t *) args = tv.tv_sec;
-    LOG_D("RTC: get rtc_time %x\n", *(rt_uint32_t *)args);
+    LOG_D("RTC: get rtc_time %x", *(rt_uint32_t *)args);
 
     return RT_EOK;
 }
@@ -262,7 +262,7 @@ static rt_err_t stm32_rtc_set_secs(void *args)
     {
         result = -RT_ERROR;
     }
-    LOG_D("RTC: set rtc_time %x\n", *(rt_uint32_t *)args);
+    LOG_D("RTC: set rtc_time %x", *(rt_uint32_t *)args);
 
     return result;
 }

components/libc/compilers/common/time.c

@@ -113,16 +113,14 @@ static rt_err_t get_timeval(struct timeval *tv)
     }
     else
     {
-        /* LOG_W will cause a recursive printing if ulog timestamp function is enabled */
-        rt_kprintf(_WARNING_NO_RTC);
+        LOG_W(_WARNING_NO_RTC);
         return -RT_ENOSYS;
     }
 
     return rst;
 
 #else
-    /* LOG_W will cause a recursive printing if ulog timestamp function is enabled */
-    rt_kprintf(_WARNING_NO_RTC);
+    LOG_W(_WARNING_NO_RTC);
     return -RT_ENOSYS;
 #endif /* RT_USING_RTC */
 }

components/utilities/ulog/backend/console_be.c

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2006-2021, RT-Thread Development Team
+ * Copyright (c) 2006-2022, RT-Thread Development Team
  *
  * SPDX-License-Identifier: Apache-2.0
  *
@@ -20,7 +20,7 @@
 static struct ulog_backend console = { 0 };
 
 void ulog_console_backend_output(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw,
-        const char *log, size_t len)
+        const char *log, rt_size_t len)
 {
 #ifdef RT_USING_DEVICE
     rt_device_t dev = rt_console_get_device();

components/utilities/ulog/syslog/syslog.c

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2006-2021, RT-Thread Development Team
+ * Copyright (c) 2006-2022, RT-Thread Development Team
  *
  * SPDX-License-Identifier: Apache-2.0
  *
@@ -170,7 +170,7 @@ static const char *get_month_str(uint8_t month)
 
 RT_WEAK rt_size_t syslog_formater(char *log_buf, int level, const char *tag, rt_bool_t newline, const char *format, va_list args)
 {
-    extern size_t ulog_strcpy(size_t cur_len, char *dst, const char *src);
+    extern rt_size_t ulog_strcpy(rt_size_t cur_len, char *dst, const char *src);
 
     rt_size_t log_len = 0, newline_len = rt_strlen(ULOG_NEWLINE_SIGN);
     int fmt_result;

components/utilities/ulog/ulog.c

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2006-2021, RT-Thread Development Team
+ * Copyright (c) 2006-2022, RT-Thread Development Team
  *
  * SPDX-License-Identifier: Apache-2.0
  *
@@ -50,7 +50,7 @@
 
 /* output log default color definition */
 #ifndef ULOG_COLOR_DEBUG
-#define ULOG_COLOR_DEBUG               NULL
+#define ULOG_COLOR_DEBUG               RT_NULL
 #endif
 #ifndef ULOG_COLOR_INFO
 #define ULOG_COLOR_INFO                (F_GREEN)
@@ -74,7 +74,7 @@ struct rt_ulog
 {
     rt_bool_t init_ok;
     rt_bool_t output_lock_enabled;
-    struct rt_semaphore output_locker;
+    struct rt_mutex output_locker;
     /* all backends */
     rt_slist_t backend_list;
     /* the thread log's line buffer */
@@ -111,35 +111,35 @@ struct rt_ulog
 /* level output info */
 static const char * const level_output_info[] =
 {
-        "A/",
-        NULL,
-        NULL,
-        "E/",
-        "W/",
-        NULL,
-        "I/",
-        "D/",
+    "A/",
+    RT_NULL,
+    RT_NULL,
+    "E/",
+    "W/",
+    RT_NULL,
+    "I/",
+    "D/",
 };
 
 #ifdef ULOG_USING_COLOR
 /* color output info */
 static const char * const color_output_info[] =
 {
-        ULOG_COLOR_ASSERT,
-        NULL,
-        NULL,
-        ULOG_COLOR_ERROR,
-        ULOG_COLOR_WARN,
-        NULL,
-        ULOG_COLOR_INFO,
-        ULOG_COLOR_DEBUG,
+    ULOG_COLOR_ASSERT,
+    RT_NULL,
+    RT_NULL,
+    ULOG_COLOR_ERROR,
+    ULOG_COLOR_WARN,
+    RT_NULL,
+    ULOG_COLOR_INFO,
+    ULOG_COLOR_DEBUG,
 };
 #endif /* ULOG_USING_COLOR */
 
 /* ulog local object */
 static struct rt_ulog ulog = { 0 };
 
-size_t ulog_strcpy(size_t cur_len, char *dst, const char *src)
+rt_size_t ulog_strcpy(rt_size_t cur_len, char *dst, const char *src)
 {
     const char *src_old = src;
 
@@ -161,9 +161,9 @@ size_t ulog_strcpy(size_t cur_len, char *dst, const char *src)
     return src - src_old;
 }
 
-size_t ulog_ultoa(char *s, unsigned long int n)
+rt_size_t ulog_ultoa(char *s, unsigned long int n)
 {
-    size_t i = 0, j = 0, len = 0;
+    rt_size_t i = 0, j = 0, len = 0;
     char swap;
 
     do
@@ -183,13 +183,16 @@ size_t ulog_ultoa(char *s, unsigned long int n)
 
 static void output_unlock(void)
 {
-    if (!ulog.output_lock_enabled)
+    /* earlier stage */
+    if (ulog.output_lock_enabled == RT_FALSE)
+    {
         return;
+    }
 
     /* If the scheduler is started and in thread context */
     if (rt_interrupt_get_nest() == 0 && rt_thread_self() != RT_NULL)
     {
-        rt_sem_release(&ulog.output_locker);
+        rt_mutex_release(&ulog.output_locker);
     }
     else
     {
@@ -201,13 +204,16 @@ static void output_unlock(void)
 
 static void output_lock(void)
 {
-    if (!ulog.output_lock_enabled)
+    /* earlier stage */
+    if (ulog.output_lock_enabled == RT_FALSE)
+    {
         return;
+    }
 
     /* If the scheduler is started and in thread context */
     if (rt_interrupt_get_nest() == 0 && rt_thread_self() != RT_NULL)
     {
-        rt_sem_take(&ulog.output_locker, RT_WAITING_FOREVER);
+        rt_mutex_take(&ulog.output_locker, RT_WAITING_FOREVER);
     }
     else
     {
@@ -235,7 +241,7 @@ static char *get_log_buf(void)
         return ulog.log_buf_isr;
 #else
         rt_kprintf("Error: Current mode not supported run in ISR. Please enable ULOG_USING_ISR_LOG.\n");
-        return NULL;
+        return RT_NULL;
 #endif
     }
 }
@@ -274,7 +280,7 @@ RT_WEAK rt_size_t ulog_formater(char *log_buf, rt_uint32_t level, const char *ta
         static struct tm *tm, tm_tmp;
         static rt_bool_t check_usec_support = RT_FALSE, usec_is_support = RT_FALSE;
 
-        if (gettimeofday(&now, NULL) >= 0)
+        if (gettimeofday(&now, RT_NULL) >= 0)
         {
             time_t t = now.tv_sec;
             tm = localtime_r(&t, &tm_tmp);
@@ -287,7 +293,7 @@ RT_WEAK rt_size_t ulog_formater(char *log_buf, rt_uint32_t level, const char *ta
                 long old_usec = now.tv_usec;
                 /* delay some time for wait microseconds changed */
                 rt_thread_mdelay(10);
-                gettimeofday(&now, NULL);
+                gettimeofday(&now, RT_NULL);
                 check_usec_support = RT_TRUE;
                 /* the microseconds is not equal between two gettimeofday calls */
                 if (now.tv_usec != old_usec)
@@ -526,8 +532,8 @@ static void do_output(rt_uint32_t level, const char *tag, rt_bool_t is_raw, cons
         /* We can't ensure that all backends support ISR context output.
          * So only using rt_kprintf when context is ISR */
         extern void ulog_console_backend_output(struct ulog_backend *backend, rt_uint32_t level, const char *tag,
-                rt_bool_t is_raw, const char *log, size_t len);
-        ulog_console_backend_output(NULL, level, tag, is_raw, log_buf, log_len);
+                rt_bool_t is_raw, const char *log, rt_size_t len);
+        ulog_console_backend_output(RT_NULL, level, tag, is_raw, log_buf, log_len);
 #endif /* ULOG_BACKEND_USING_CONSOLE */
     }
 #endif /* ULOG_USING_ASYNC_OUTPUT */
@@ -544,17 +550,18 @@ static void do_output(rt_uint32_t level, const char *tag, rt_bool_t is_raw, cons
  */
 void ulog_voutput(rt_uint32_t level, const char *tag, rt_bool_t newline, const char *format, va_list args)
 {
-    char *log_buf = NULL;
+    static rt_bool_t ulog_voutput_recursion = RT_FALSE;
+    char *log_buf = RT_NULL;
     rt_size_t log_len = 0;
 
+    RT_ASSERT(tag);
+    RT_ASSERT(format);
 #ifndef ULOG_USING_SYSLOG
     RT_ASSERT(level <= LOG_LVL_DBG);
 #else
     RT_ASSERT(LOG_PRI(level) <= LOG_DEBUG);
 #endif /* ULOG_USING_SYSLOG */
 
-    RT_ASSERT(tag);
-    RT_ASSERT(format);
 
     if (!ulog.init_ok)
     {
@@ -577,7 +584,6 @@ void ulog_voutput(rt_uint32_t level, const char *tag, rt_bool_t newline, const c
 #endif /* ULOG_USING_SYSLOG */
     else if (!rt_strstr(tag, ulog.filter.tag))
     {
-        /* tag filter */
         return;
     }
 #endif /* ULOG_USING_FILTER */
@@ -588,6 +594,20 @@ void ulog_voutput(rt_uint32_t level, const char *tag, rt_bool_t newline, const c
     /* lock output */
     output_lock();
 
+    /* If there is a recursion, we use a simple way */
+    if (ulog_voutput_recursion == RT_TRUE)
+    {
+        rt_kprintf(format, args);
+        if(newline == RT_TRUE)
+        {
+            rt_kprintf(ULOG_NEWLINE_SIGN);
+        }
+        output_unlock();
+        return;
+    }
+
+    ulog_voutput_recursion = RT_TRUE;
+
 #ifndef ULOG_USING_SYSLOG
     log_len = ulog_formater(log_buf, level, tag, newline, format, args);
 #else
@@ -604,6 +624,7 @@ void ulog_voutput(rt_uint32_t level, const char *tag, rt_bool_t newline, const c
         /* find the keyword */
         if (!rt_strstr(log_buf, ulog.filter.keyword))
         {
+            ulog_voutput_recursion = RT_FALSE;
             /* unlock output */
             output_unlock();
             return;
@@ -613,6 +634,8 @@ void ulog_voutput(rt_uint32_t level, const char *tag, rt_bool_t newline, const c
     /* do log output */
     do_output(level, tag, RT_FALSE, log_buf, log_len);
 
+    ulog_voutput_recursion = RT_FALSE;
+
     /* unlock output */
     output_unlock();
 }
@@ -647,14 +670,14 @@ void ulog_output(rt_uint32_t level, const char *tag, rt_bool_t newline, const ch
 void ulog_raw(const char *format, ...)
 {
     rt_size_t log_len = 0;
-    char *log_buf = NULL;
+    char *log_buf = RT_NULL;
     va_list args;
     int fmt_result;
 
     RT_ASSERT(ulog.init_ok);
 
 #ifdef ULOG_USING_ASYNC_OUTPUT
-    if (ulog.async_rb == NULL)
+    if (ulog.async_rb == RT_NULL)
     {
         ulog.async_rb = rt_ringbuffer_create(ULOG_ASYNC_OUTPUT_BUF_SIZE);
     }
@@ -682,7 +705,7 @@ void ulog_raw(const char *format, ...)
     }
 
     /* do log output */
-    do_output(LOG_LVL_DBG, NULL, RT_TRUE, log_buf, log_len);
+    do_output(LOG_LVL_DBG, RT_NULL, RT_TRUE, log_buf, log_len);
 
     /* unlock output */
     output_unlock();
@@ -705,7 +728,7 @@ void ulog_hexdump(const char *tag, rt_size_t width, rt_uint8_t *buf, rt_size_t s
 #ifdef ULOG_OUTPUT_TIME
     rt_size_t time_head_len = 0;
 #endif
-    char *log_buf = NULL, dump_string[8];
+    char *log_buf = RT_NULL, dump_string[8];
     int fmt_result;
 
     RT_ASSERT(ulog.init_ok);
@@ -747,7 +770,7 @@ void ulog_hexdump(const char *tag, rt_size_t width, rt_uint8_t *buf, rt_size_t s
             static time_t now;
             static struct tm *tm, tm_tmp;
 
-            now = time(NULL);
+            now = time(RT_NULL);
             tm = gmtime_r(&now, &tm_tmp);
 
 #ifdef RT_USING_SOFT_RTC
@@ -829,7 +852,7 @@ void ulog_hexdump(const char *tag, rt_size_t width, rt_uint8_t *buf, rt_size_t s
         /*add string end sign*/
         log_buf[log_len] = '\0';
         /* do log output */
-        do_output(LOG_LVL_DBG, NULL, RT_TRUE, log_buf, log_len);
+        do_output(LOG_LVL_DBG, RT_NULL, RT_TRUE, log_buf, log_len);
     }
     /* unlock output */
     output_unlock();
@@ -896,7 +919,7 @@ int ulog_be_lvl_filter_set(const char *be_name, rt_uint32_t level)
 int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level)
 {
     rt_slist_t *node;
-    ulog_tag_lvl_filter_t tag_lvl = NULL;
+    ulog_tag_lvl_filter_t tag_lvl = RT_NULL;
     int result = RT_EOK;
 
     if (level > LOG_FILTER_LVL_ALL)
@@ -917,7 +940,7 @@ int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level)
         }
         else
         {
-            tag_lvl = NULL;
+            tag_lvl = RT_NULL;
         }
     }
     /* find OK */
@@ -972,7 +995,7 @@ int ulog_tag_lvl_filter_set(const char *tag, rt_uint32_t level)
 rt_uint32_t ulog_tag_lvl_filter_get(const char *tag)
 {
     rt_slist_t *node;
-    ulog_tag_lvl_filter_t tag_lvl = NULL;
+    ulog_tag_lvl_filter_t tag_lvl = RT_NULL;
     rt_uint32_t level = LOG_FILTER_LVL_ALL;
 
     if (!ulog.init_ok)
@@ -1209,7 +1232,7 @@ static void ulog_filter(uint8_t argc, char **argv)
 #endif
     const char *tag = ulog_global_filter_tag_get(), *kw = ulog_global_filter_kw_get();
     rt_slist_t *node;
-    ulog_tag_lvl_filter_t tag_lvl = NULL;
+    ulog_tag_lvl_filter_t tag_lvl = RT_NULL;
 
     rt_kprintf("--------------------------------------\n");
     rt_kprintf("ulog global filter:\n");
@@ -1349,7 +1372,7 @@ void ulog_async_output(void)
         return;
     }
 
-    while ((log_blk = rt_rbb_blk_get(ulog.async_rbb)) != NULL)
+    while ((log_blk = rt_rbb_blk_get(ulog.async_rbb)) != RT_NULL)
     {
         log_frame = (ulog_frame_t) log_blk->buf;
         if (log_frame->magic == ULOG_FRAME_MAGIC)
@@ -1363,12 +1386,12 @@ void ulog_async_output(void)
     /* output the log_raw format log */
     if (ulog.async_rb)
     {
-        size_t log_len = rt_ringbuffer_data_len(ulog.async_rb);
+        rt_size_t log_len = rt_ringbuffer_data_len(ulog.async_rb);
         char *log = rt_malloc(log_len);
         if (log)
         {
-            size_t len = rt_ringbuffer_get(ulog.async_rb, (rt_uint8_t *)log, log_len);
-            ulog_output_to_all_backend(LOG_LVL_DBG, NULL, RT_TRUE, log, len);
+            rt_size_t len = rt_ringbuffer_get(ulog.async_rb, (rt_uint8_t *)log, log_len);
+            ulog_output_to_all_backend(LOG_LVL_DBG, RT_NULL, RT_TRUE, log, len);
             rt_free(log);
         }
     }
@@ -1439,7 +1462,7 @@ int ulog_init(void)
     if (ulog.init_ok)
         return 0;
 
-    rt_sem_init(&ulog.output_locker, "ulog lock", 1, RT_IPC_FLAG_FIFO);
+    rt_mutex_init(&ulog.output_locker, "ulog", RT_IPC_FLAG_PRIO);
     ulog.output_lock_enabled = RT_TRUE;
     rt_slist_init(&ulog.backend_list);
 
@@ -1452,10 +1475,10 @@ int ulog_init(void)
     ulog.async_enabled = RT_TRUE;
     /* async output ring block buffer */
     ulog.async_rbb = rt_rbb_create(RT_ALIGN(ULOG_ASYNC_OUTPUT_BUF_SIZE, RT_ALIGN_SIZE), ULOG_ASYNC_OUTPUT_STORE_LINES);
-    if (ulog.async_rbb == NULL)
+    if (ulog.async_rbb == RT_NULL)
     {
         rt_kprintf("Error: ulog init failed! No memory for async rbb.\n");
-        rt_sem_detach(&ulog.output_locker);
+        rt_mutex_detach(&ulog.output_locker);
         return -RT_ENOMEM;
     }
     rt_sem_init(&ulog.async_notice, "ulog", 0, RT_IPC_FLAG_FIFO);
@@ -1474,12 +1497,12 @@ INIT_BOARD_EXPORT(ulog_init);
 #ifdef ULOG_USING_ASYNC_OUTPUT
 int ulog_async_init(void)
 {
-    if (ulog.async_th == NULL)
+    if (ulog.async_th == RT_NULL)
     {
         /* async output thread */
         ulog.async_th = rt_thread_create("ulog_async", async_output_thread_entry, &ulog, ULOG_ASYNC_OUTPUT_THREAD_STACK,
                 ULOG_ASYNC_OUTPUT_THREAD_PRIORITY, 20);
-        if (ulog.async_th == NULL)
+        if (ulog.async_th == RT_NULL)
         {
             rt_kprintf("Error: ulog init failed! No memory for async output thread.\n");
             return -RT_ENOMEM;
@@ -1522,7 +1545,7 @@ void ulog_deinit(void)
     }
 #endif /* ULOG_USING_FILTER */
 
-    rt_sem_detach(&ulog.output_locker);
+    rt_mutex_detach(&ulog.output_locker);
 
 #ifdef ULOG_USING_ASYNC_OUTPUT
     rt_rbb_destroy(ulog.async_rbb);

components/utilities/ulog/ulog.h

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2006-2021, RT-Thread Development Team
+ * Copyright (c) 2006-2022, RT-Thread Development Team
  *
  * SPDX-License-Identifier: Apache-2.0
  *
@@ -18,8 +18,6 @@
 extern "C" {
 #endif
 
-#define ULOG_VERSION_STR               "0.1.1"
-
 /*
  * ulog init and deint
  */
@@ -42,12 +40,12 @@ void ulog_deinit(void);
  * LOG_D("this is a debug log!");
  * LOG_E("this is a error log!");
  */
-#define LOG_E(...)                     ulog_e(LOG_TAG, __VA_ARGS__)
-#define LOG_W(...)                     ulog_w(LOG_TAG, __VA_ARGS__)
-#define LOG_I(...)                     ulog_i(LOG_TAG, __VA_ARGS__)
-#define LOG_D(...)                     ulog_d(LOG_TAG, __VA_ARGS__)
-#define LOG_RAW(...)                   ulog_raw(__VA_ARGS__)
-#define LOG_HEX(name, width, buf, size)      ulog_hex(name, width, buf, size)
+#define LOG_E(...)                      ulog_e(LOG_TAG, __VA_ARGS__)
+#define LOG_W(...)                      ulog_w(LOG_TAG, __VA_ARGS__)
+#define LOG_I(...)                      ulog_i(LOG_TAG, __VA_ARGS__)
+#define LOG_D(...)                      ulog_d(LOG_TAG, __VA_ARGS__)
+#define LOG_RAW(...)                    ulog_raw(__VA_ARGS__)
+#define LOG_HEX(name, width, buf, size) ulog_hex(name, width, buf, size)
 
 /*
  * backend register and unregister

components/utilities/ulog/ulog_def.h

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2006-2021, RT-Thread Development Team
+ * Copyright (c) 2006-2022, RT-Thread Development Team
  *
  * SPDX-License-Identifier: Apache-2.0
  *
@@ -11,9 +11,6 @@
 #ifndef _ULOG_DEF_H_
 #define _ULOG_DEF_H_
 
-#include <stddef.h>
-#include <stdint.h>
-#include <stdlib.h>
 #include <rtdef.h>
 
 #ifdef __cplusplus
@@ -208,15 +205,15 @@ struct ulog_backend
     rt_bool_t support_color;
     rt_uint32_t out_level;
     void (*init)  (struct ulog_backend *backend);
-    void (*output)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, size_t len);
+    void (*output)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, rt_size_t len);
     void (*flush) (struct ulog_backend *backend);
     void (*deinit)(struct ulog_backend *backend);
     /* The filter will be call before output. It will return TRUE when the filter condition is math. */
-    rt_bool_t (*filter)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, size_t len);
+    rt_bool_t (*filter)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, rt_size_t len);
     rt_slist_t list;
 };
 typedef struct ulog_backend *ulog_backend_t;
-typedef rt_bool_t (*ulog_backend_filter_t)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, size_t len);
+typedef rt_bool_t (*ulog_backend_filter_t)(struct ulog_backend *backend, rt_uint32_t level, const char *tag, rt_bool_t is_raw, const char *log, rt_size_t len);
 
 #ifdef __cplusplus
 }