Unify stdio logging (#34070)

* Unify stdio logging

Darwin now uses the same stdio logging implementation as other platforms.
Logs are colorized and contain timestamps.
On linux and darwin, pid and tid are also logged.

* Darwin formatting

* Fix cirque test driver

* Log seconds and milliseconds

* Update Logging.cpp

Author: mbknust

src/platform/logging/BUILD.gn

@@ -109,11 +109,7 @@ if (current_os == "android") {
 stdio_archive = "$root_out_dir/liblogging-stdio.a"
 
 source_set("stdio") {
-  if (chip_device_platform == "darwin") {
-    sources = [ "impl/stdio/darwin/Logging.cpp" ]
-  } else {
-    sources = [ "impl/stdio/Logging.cpp" ]
-  }
+  sources = [ "impl/stdio/Logging.cpp" ]
 
   deps = [
     ":headers",

src/platform/logging/impl/stdio/Logging.cpp

@@ -4,17 +4,65 @@
 
 #include <lib/support/logging/Constants.h>
 
+#include <inttypes.h>
 #include <stdio.h>
+#include <time.h>
+
+#if defined(__APPLE__)
+#include <pthread.h>
+#include <unistd.h>
+#elif defined(__gnu_linux__)
+#include <sys/syscall.h>
+#include <unistd.h>
+#endif
 
 namespace chip {
 namespace Logging {
 namespace Platform {
 
+// TODO: investigate whether pw_chrono or pw_log could be used here
 void LogV(const char * module, uint8_t category, const char * msg, va_list v)
 {
-    printf("CHIP:%s: ", module);
+    // Stdout needs to be locked, because it's printed in pieces
+#if defined(_POSIX_THREAD_SAFE_FUNCTIONS)
+    flockfile(stdout);
+#endif
+
+    switch (category)
+    {
+    case kLogCategory_Error:
+        printf("\033[1;31m");
+        break;
+    case kLogCategory_Progress:
+        printf("\033[0;32m");
+        break;
+    case kLogCategory_Detail:
+        printf("\033[0;34m");
+        break;
+    }
+
+#if defined(__APPLE__) || defined(__gnu_linux__)
+    timespec ts;
+    timespec_get(&ts, TIME_UTC);
+    printf("[%lld.%03ld] ", static_cast<long long>(ts.tv_sec), static_cast<long>(ts.tv_nsec / 1000000));
+#endif
+
+#if defined(__APPLE__)
+    uint64_t ktid;
+    pthread_threadid_np(nullptr, &ktid);
+    printf("[%lld:%lld] ", static_cast<long long>(getpid()), static_cast<long long>(ktid));
+#elif defined(__gnu_linux__) && !defined(__NuttX__)
+    // TODO: change to getpid() and gettid() after glib upgrade
+    printf("[%lld:%lld] ", static_cast<long long>(syscall(SYS_getpid)), static_cast<long long>(syscall(SYS_gettid)));
+#endif
+
+    printf("[%s] ", module);
     vprintf(msg, v);
-    printf("\n");
+    printf("\033[0m\n");
+
+#if defined(_POSIX_THREAD_SAFE_FUNCTIONS)
+    funlockfile(stdout);
+#endif
 }
 
 } // namespace Platform

src/platform/logging/impl/stdio/darwin/Logging.cpp

@@ -145,7 +145,7 @@ def reset_thread_devices(self, devices: Union[List[str], str]):
             self.assertTrue(self.wait_for_device_output(
                 device_id, "Thread Border Router started on AIL", 10))
             self.assertTrue(self.wait_for_device_output(
-                device_id, "CHIP:SVR: Server Listening...", 15))
+                device_id, "[SVR] Server Listening...", 15))
             # Clear default Thread network commissioning data
             self.logger.info("Resetting thread network on {}".format(
                 self.get_device_pretty_id(device_id)))