[ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros (#26348)

* [ESP32] Use esp_log_writev() for logging rather than ESP_LOGx macros

Basically this unreverts the #26282 with additional changes to fixed
the rpc logging problem introduced in #26227.

* Fix the bug when setting the log level

* remove the log level check

* Fix the color codes for pigweed logs

* Added comment explaining the addition of color codes in pigweed logger

Author: shubhamdp

config/esp32/components/chip/CMakeLists.txt

@@ -86,10 +86,29 @@ chip_gn_arg_append("esp32_cpu"             "\"esp32\"")
 chip_gn_arg_bool("is_debug"                ${is_debug})
 
 # Config the chip log level by IDF menuconfig
-chip_gn_arg_bool  ("chip_error_logging"        CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 1)
-chip_gn_arg_bool  ("chip_progress_logging"     CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 3)
-chip_gn_arg_bool  ("chip_detail_logging"       CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 4)
-chip_gn_arg_bool  ("chip_automation_logging"   CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 5)
+if (CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 1)
+    chip_gn_arg_bool  ("chip_error_logging" "true")
+else()
+    chip_gn_arg_bool  ("chip_error_logging" "false")
+endif()
+
+if (CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 3)
+    chip_gn_arg_bool  ("chip_progress_logging" "true")
+else()
+    chip_gn_arg_bool  ("chip_progress_logging" "false")
+endif()
+
+if (CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 4)
+    chip_gn_arg_bool  ("chip_detail_logging" "true")
+else()
+    chip_gn_arg_bool  ("chip_detail_logging" "false")
+endif()
+
+if (CONFIG_LOG_DEFAULT_LEVEL GREATER_EQUAL 5)
+    chip_gn_arg_bool  ("chip_automation_logging" "true")
+else()
+    chip_gn_arg_bool  ("chip_automation_logging" "false")
+endif()
 
 if(CONFIG_ENABLE_CHIPOBLE)
 chip_gn_arg_append("chip_config_network_layer_ble"           "true")
@@ -373,8 +392,10 @@ target_link_libraries(${COMPONENT_LIB} INTERFACE -Wl,--start-group
 add_dependencies(${COMPONENT_LIB} chip_gn)
 
 if(CONFIG_ENABLE_PW_RPC)
-    set(WRAP_FUNCTIONS esp_log_write)
-    target_link_libraries(${COMPONENT_LIB} INTERFACE "-Wl,--wrap=${WRAP_FUNCTIONS}")
+    set(WRAP_FUNCTIONS esp_log_write esp_log_writev)
+    foreach(func ${WRAP_FUNCTIONS})
+        target_link_libraries(${COMPONENT_LIB} INTERFACE "-Wl,--wrap=${func}")
+    endforeach()
 endif()
 
 # Build Matter OTA image

examples/platform/esp32/PigweedLogger.cpp

@@ -86,6 +86,28 @@ SemaphoreHandle_t * getSemaphore()
     return &esp_log_mutex;
 }
 
+static const char * getLogColorForLevel(esp_log_level_t level)
+{
+    switch (level)
+    {
+    case ESP_LOG_ERROR:
+        return LOG_COLOR_E "E";
+
+    case ESP_LOG_INFO:
+        return LOG_COLOR_I "I";
+
+    default:
+        // default is kept as ESP_LOG_DEBUG
+        return LOG_COLOR_D "D";
+    }
+}
+
+// ESP_LOGx(...) logs are funneled to esp_log_write() and it has the specific format. It contains color codes,
+// log level character, timestamp, tag, and actual log message. Everything here is part of format and variadic argument.
+//
+// ChipLogx(...) logs are funneled to esp_log_writev() will only have actual log message without color codes, log level
+// character, timestamp, and tag. So, to match up __wrap_esp_log_writev() adds those details when sending log to pigweed
+// logger.
 extern "C" void __wrap_esp_log_write(esp_log_level_t level, const char * tag, const char * format, ...)
 {
     va_list v;
@@ -107,4 +129,30 @@ extern "C" void __wrap_esp_log_write(esp_log_level_t level, const char * tag, co
     va_end(v);
 }
 
+extern "C" void __wrap_esp_log_writev(esp_log_level_t level, const char * tag, const char * format, va_list v)
+{
+#ifndef CONFIG_LOG_DEFAULT_LEVEL_NONE
+    if (uartInitialised && level <= CONFIG_LOG_MAXIMUM_LEVEL)
+    {
+        const char * logColor = getLogColorForLevel(level);
+        PigweedLogger::putString(logColor, strlen(logColor));
+
+        char formattedMsg[CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE];
+        size_t len = snprintf(formattedMsg, sizeof formattedMsg, " (%u) %s: ", esp_log_timestamp(), tag);
+        PigweedLogger::putString(formattedMsg, len);
+
+        memset(formattedMsg, 0, sizeof formattedMsg);
+        len = vsnprintf(formattedMsg, sizeof formattedMsg, format, v);
+        if (len >= sizeof formattedMsg)
+        {
+            len = sizeof formattedMsg - 1;
+        }
+        PigweedLogger::putString(formattedMsg, len);
+
+        const char * logResetColor = LOG_RESET_COLOR "\n";
+        PigweedLogger::putString(logResetColor, strlen(logResetColor));
+    }
+#endif
+}
+
 } // namespace PigweedLogger

src/platform/ESP32/Logging.cpp

@@ -26,21 +26,35 @@ void ENFORCE_FORMAT(3, 0) LogV(const char * module, uint8_t category, const char
     snprintf(tag, sizeof(tag), "chip[%s]", module);
     tag[sizeof(tag) - 1] = 0;
 
-    char formattedMsg[CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE];
-    vsnprintf(formattedMsg, sizeof(formattedMsg), msg, v);
-
     switch (category)
     {
-    case kLogCategory_Error:
-        ESP_LOGE(tag, "%s", formattedMsg);
-        break;
+    case kLogCategory_Error: {
+        {
+            printf(LOG_COLOR_E "E (%u) %s: ", esp_log_timestamp(), tag);
+            esp_log_writev(ESP_LOG_ERROR, tag, msg, v);
+            printf(LOG_RESET_COLOR "\n");
+        }
+    }
+    break;
+
     case kLogCategory_Progress:
-    default:
-        ESP_LOGI(tag, "%s", formattedMsg);
-        break;
-    case kLogCategory_Detail:
-        ESP_LOGD(tag, "%s", formattedMsg);
-        break;
+    default: {
+        {
+            printf(LOG_COLOR_I "I (%u) %s: ", esp_log_timestamp(), tag);
+            esp_log_writev(ESP_LOG_INFO, tag, msg, v);
+            printf(LOG_RESET_COLOR "\n");
+        }
+    }
+    break;
+
+    case kLogCategory_Detail: {
+        {
+            printf(LOG_COLOR_D "D (%u) %s: ", esp_log_timestamp(), tag);
+            esp_log_writev(ESP_LOG_DEBUG, tag, msg, v);
+            printf(LOG_RESET_COLOR "\n");
+        }
+    }
+    break;
     }
 }