RPC: Support pw logging for linux rpc examples (#20057)

Add a config option CHIP_USE_PW_LOGGING, which uses pw log output
instead of printf on linux. This allows the logs to correctly get
HDLC encoded and be piped over the socket for linux RPC builds.

Author: rgoliver

examples/chef/linux/with_pw_rpc.gni

@@ -40,3 +40,4 @@ pw_build_LINK_DEPS = [
 
 chip_enable_pw_rpc = true
 chip_build_pw_trace_lib = true
+chip_use_pw_logging = true

examples/common/pigweed/rpc_console/py/chip_rpc/console.py

@@ -253,7 +253,8 @@ def write_to_output(data: bytes,
                      "E": logging.ERROR, "F": logging.FATAL, "V": logging.DEBUG, "D": logging.DEBUG,
                      "<inf>": logging.INFO, "<dbg>": logging.DEBUG, "<err>": logging.ERROR,
                      "<info  >": logging.INFO, "<warn  >": logging.WARNING,
-                     "<error >": logging.ERROR, "<detail>": logging.DEBUG}
+                     "<error >": logging.ERROR, "<detail>": logging.DEBUG,
+                     "ERR": logging.ERROR, "DBG": logging.DEBUG, "INF": logging.INFO}
 
     ESP_CHIP_REGEX = r"(?P<level>[IWEFV]) \((?P<time>\d+)\) (?P<mod>chip\[[a-zA-Z]+\]):\s(?P<msg>.*)"
     ESP_APP_REGEX = r"(?P<level>[IWEFVD]) \((?P<time>\d+)\) (?P<mod>[a-z\-_A-Z]+):\s(?P<msg>.*)"
@@ -267,14 +268,17 @@ def write_to_output(data: bytes,
     NXP_CHIP_REGEX = r"\[(?P<time>\d+)\]\[(?P<level>[EPDF])\]\[(?P<mod>[a-z\-A-Z]+)\](?P<msg>.*)"
     NXP_APP_REGEX = r"\[(?P<time>\d+)\]\[(?P<mod>[a-z\-A-Z]+)\](?P<msg>.*)"
 
+    LINUX_REGEX = r".*(?P<level>INF|DBG|ERR).*\s+\[(?P<time>[0-9]+\.?[0-9]*)\]\[(?P<pid>\d+)\:(?P<tid>\d+)\] CHIP:(?P<mod>[a-z\-A-Z]+)\: (?P<msg>.*)"
+
     LogRegexes = [RegexStruct("ESP", "CHIP", re.compile(ESP_CHIP_REGEX), 4),
                   RegexStruct("ESP", "APP", re.compile(ESP_APP_REGEX), 4),
                   RegexStruct("EFR", "CHIP", re.compile(EFR_CHIP_REGEX), 3),
                   RegexStruct("EFR", "APP", re.compile(EFR_APP_REGEX), 1),
                   RegexStruct("NRF", "CHIP", re.compile(NRF_CHIP_REGEX), 4),
                   RegexStruct("NRF", "APP", re.compile(NRF_APP_REGEX), 3),
                   RegexStruct("NXP", "CHIP", re.compile(NXP_CHIP_REGEX), 4),
-                  RegexStruct("NXP", "APP", re.compile(NXP_APP_REGEX), 3)
+                  RegexStruct("NXP", "APP", re.compile(NXP_APP_REGEX), 3),
+                  RegexStruct("LINUX", "CHIP", re.compile(LINUX_REGEX), 6)
                   ]
     for line in log_line.decode(errors="surrogateescape").splitlines():
         fields = {'level': logging.INFO, "time": "",

examples/lighting-app/linux/with_pw_rpc.gni

@@ -40,3 +40,4 @@ pw_build_LINK_DEPS = [
 
 chip_enable_pw_rpc = true
 chip_build_pw_trace_lib = true
+chip_use_pw_logging = true

src/lib/core/BUILD.gn

@@ -47,6 +47,7 @@ buildconfig_header("chip_buildconfig") {
     "CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE=${chip_log_message_max_size}",
     "CHIP_AUTOMATION_LOGGING=${chip_automation_logging}",
     "CHIP_PW_TOKENIZER_LOGGING=${chip_pw_tokenizer_logging}",
+    "CHIP_USE_PW_LOGGING=${chip_use_pw_logging}",
     "CHIP_CONFIG_SHORT_ERROR_STR=${chip_config_short_error_str}",
     "CHIP_CONFIG_ENABLE_ARG_PARSER=${chip_config_enable_arg_parser}",
     "CHIP_TARGET_STYLE_UNIX=${chip_target_style_unix}",

src/lib/core/core.gni

@@ -44,6 +44,9 @@ declare_args() {
   # Enable pigweed tokenizer logging.
   chip_pw_tokenizer_logging = false
 
+  # Configure chip logging to output through pigweed logging.
+  chip_use_pw_logging = false
+
   # Enable short error strings.
   chip_config_short_error_str = false
 

src/platform/Linux/BUILD.gn

@@ -17,10 +17,15 @@ import("//build_overrides/chip.gni")
 
 import("${build_root}/config/linux/pkg_config.gni")
 
+import("${chip_root}/src/lib/core/core.gni")
 import("${chip_root}/src/platform/device.gni")
 
 assert(chip_device_platform == "linux")
 
+if (chip_use_pw_logging) {
+  import("//build_overrides/pigweed.gni")
+}
+
 if (chip_enable_openthread) {
   import("//build_overrides/openthread.gni")
   import("//build_overrides/ot_br_posix.gni")
@@ -125,6 +130,10 @@ static_library("Linux") {
     public_deps += [ "dbus/openthread" ]
   }
 
+  if (chip_use_pw_logging) {
+    deps += [ "$dir_pw_log" ]
+  }
+
   if (chip_enable_wifi) {
     sources += [ "GlibTypeDeleter.h" ]
 

src/platform/Linux/Logging.cpp

@@ -1,15 +1,21 @@
 /* See Project CHIP LICENSE file for licensing information. */
 
+#include <lib/core/CHIPConfig.h>
 #include <lib/support/EnforceFormat.h>
 #include <lib/support/logging/Constants.h>
 #include <platform/logging/LogV.h>
 
 #include <cinttypes>
 #include <cstdio>
+#include <cstring>
 #include <sys/syscall.h>
 #include <sys/time.h>
 #include <unistd.h>
 
+#if CHIP_USE_PW_LOGGING
+#include <pw_log/log.h>
+#endif // CHIP_USE_PW_LOGGING
+
 namespace chip {
 namespace DeviceLayer {
 
@@ -37,6 +43,7 @@ void ENFORCE_FORMAT(3, 0) LogV(const char * module, uint8_t category, const char
     // indicate the error occurred during getting time.
     gettimeofday(&tv, nullptr);
 
+#if !CHIP_USE_PW_LOGGING
     // Lock standard output, so a single log line will not be corrupted in case
     // where multiple threads are using logging subsystem at the same time.
     flockfile(stdout);
@@ -48,6 +55,30 @@ void ENFORCE_FORMAT(3, 0) LogV(const char * module, uint8_t category, const char
     fflush(stdout);
 
     funlockfile(stdout);
+#else  // !CHIP_USE_PW_LOGGING
+    char formattedMsg[CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE];
+    snprintf(formattedMsg, sizeof(formattedMsg),
+             "[%" PRIu64 ".%06" PRIu64 "][%lld:%lld] CHIP:%s: ", static_cast<uint64_t>(tv.tv_sec),
+             static_cast<uint64_t>(tv.tv_usec), static_cast<long long>(syscall(SYS_getpid)),
+             static_cast<long long>(syscall(SYS_gettid)), module);
+    size_t len = strnlen(formattedMsg, sizeof(formattedMsg));
+    vsnprintf(formattedMsg + len, sizeof(formattedMsg) - len, msg, v);
+
+    switch (static_cast<LogCategory>(category))
+    {
+    case kLogCategory_Error:
+        PW_LOG_ERROR("%s", formattedMsg);
+        break;
+    case kLogCategory_Progress:
+        PW_LOG_INFO("%s", formattedMsg);
+        break;
+    case kLogCategory_Detail:
+    case kLogCategory_None:
+    case kLogCategory_Automation:
+        PW_LOG_DEBUG("%s", formattedMsg);
+        break;
+    }
+#endif // !CHIP_USE_PW_LOGGING
 
     // Let the application know that a log message has been emitted.
     DeviceLayer::OnLogOutput();