From d098f118e7c9b964a34843890291f77fe7b2e2d4 Mon Sep 17 00:00:00 2001 From: Maksymilian Knust Date: Tue, 25 Jun 2024 12:01:54 +0200 Subject: [PATCH 1/5] 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. --- src/platform/logging/BUILD.gn | 6 +- src/platform/logging/impl/stdio/Logging.cpp | 49 ++++++++++++- .../logging/impl/stdio/darwin/Logging.cpp | 72 ------------------- 3 files changed, 49 insertions(+), 78 deletions(-) delete mode 100644 src/platform/logging/impl/stdio/darwin/Logging.cpp diff --git a/src/platform/logging/BUILD.gn b/src/platform/logging/BUILD.gn index 6b914cab7357d2..632c4ee5353224 100644 --- a/src/platform/logging/BUILD.gn +++ b/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", diff --git a/src/platform/logging/impl/stdio/Logging.cpp b/src/platform/logging/impl/stdio/Logging.cpp index c403c29b913293..65bfe94b00b8e9 100644 --- a/src/platform/logging/impl/stdio/Logging.cpp +++ b/src/platform/logging/impl/stdio/Logging.cpp @@ -4,17 +4,64 @@ #include +#include #include +#include + +#if defined(__APPLE__) +#include +#include +#elif defined(__gnu_linux__) +#include +#include +#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) { +#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.%06ld] ", static_cast(ts.tv_sec), static_cast(ts.tv_nsec / 1000)); +#endif + +#if defined(__APPLE__) + uint64_t ktid; + pthread_threadid_np(nullptr, &ktid); + printf("[%lld:%lld] ", static_cast(getpid()), static_cast(ktid)); +#elif defined(__gnu_linux__) && !defined(__NuttX__) + // TODO: change to getpid() and gettid() after glib upgrade + printf("[%lld:%lld] ", static_cast(syscall(SYS_getpid)), static_cast(syscall(SYS_gettid))); +#endif + printf("CHIP:%s: ", module); vprintf(msg, v); - printf("\n"); + printf("\033[0m\n"); + +#if defined(_POSIX_THREAD_SAFE_FUNCTIONS) + funlockfile(stdout); +#endif } } // namespace Platform diff --git a/src/platform/logging/impl/stdio/darwin/Logging.cpp b/src/platform/logging/impl/stdio/darwin/Logging.cpp deleted file mode 100644 index 49c58eea1d7bba..00000000000000 --- a/src/platform/logging/impl/stdio/darwin/Logging.cpp +++ /dev/null @@ -1,72 +0,0 @@ -/* - * - * Copyright (c) 2022 Project CHIP Authors - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - -#include - -#include -#include -#include -#include -#include -#include - -namespace chip { -namespace Logging { -namespace Platform { - -void LogV(const char * module, uint8_t category, const char * msg, va_list v) -{ - timeval time; - gettimeofday(&time, nullptr); - long ms = (time.tv_sec * 1000) + (time.tv_usec / 1000); - - uint64_t ktid; - pthread_threadid_np(nullptr, &ktid); - - char formattedMsg[CHIP_CONFIG_LOG_MESSAGE_MAX_SIZE]; - int32_t prefixLen = - snprintf(formattedMsg, sizeof(formattedMsg), "[%ld] [%lld:%lld] [%s] ", ms, (long long) getpid(), (long long) ktid, module); - if (prefixLen < 0) - { - // This should not happen - return; - } - - if (static_cast(prefixLen) >= sizeof(formattedMsg)) - { - prefixLen = sizeof(formattedMsg) - 1; - } - - vsnprintf(formattedMsg + prefixLen, sizeof(formattedMsg) - static_cast(prefixLen), msg, v); - - switch (category) - { - case kLogCategory_Error: - printf("\033[1;31m%s\033[0m\n", formattedMsg); - break; - case kLogCategory_Progress: - printf("\033[0;32m%s\033[0m\n", formattedMsg); - break; - case kLogCategory_Detail: - printf("\033[0;34m%s\033[0m\n", formattedMsg); - break; - } -} - -} // namespace Platform -} // namespace Logging -} // namespace chip From 25cacdc1f76c5941ab746571b5fa2bbc9cd730b3 Mon Sep 17 00:00:00 2001 From: Maksymilian Knust Date: Wed, 26 Jun 2024 09:56:07 +0200 Subject: [PATCH 2/5] Darwin formatting --- src/platform/logging/impl/stdio/Logging.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/platform/logging/impl/stdio/Logging.cpp b/src/platform/logging/impl/stdio/Logging.cpp index 65bfe94b00b8e9..99c7cd5e136ccb 100644 --- a/src/platform/logging/impl/stdio/Logging.cpp +++ b/src/platform/logging/impl/stdio/Logging.cpp @@ -23,6 +23,7 @@ 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) { + // Stdout needs to be locked, because it's printed in pieces #if defined(_POSIX_THREAD_SAFE_FUNCTIONS) flockfile(stdout); #endif @@ -43,7 +44,7 @@ void LogV(const char * module, uint8_t category, const char * msg, va_list v) #if defined(__APPLE__) || defined(__gnu_linux__) timespec ts; timespec_get(&ts, TIME_UTC); - printf("[%lld.%06ld] ", static_cast(ts.tv_sec), static_cast(ts.tv_nsec / 1000)); + printf("[%lld] ", static_cast(ts.tv_sec * 1000 + ts.tv_nsec / 1000000)); #endif #if defined(__APPLE__) @@ -55,7 +56,7 @@ void LogV(const char * module, uint8_t category, const char * msg, va_list v) printf("[%lld:%lld] ", static_cast(syscall(SYS_getpid)), static_cast(syscall(SYS_gettid))); #endif - printf("CHIP:%s: ", module); + printf("[%s] ", module); vprintf(msg, v); printf("\033[0m\n"); From 0c80072f38031de1b0bc3d4a0f34ccab701a75fb Mon Sep 17 00:00:00 2001 From: Maksymilian Knust Date: Wed, 26 Jun 2024 11:30:27 +0200 Subject: [PATCH 3/5] Fix cirque test driver --- src/test_driver/linux-cirque/helper/CHIPTestBase.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/test_driver/linux-cirque/helper/CHIPTestBase.py b/src/test_driver/linux-cirque/helper/CHIPTestBase.py index 7fd0c81e86f3ca..ea45a62221e7e5 100644 --- a/src/test_driver/linux-cirque/helper/CHIPTestBase.py +++ b/src/test_driver/linux-cirque/helper/CHIPTestBase.py @@ -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))) From f5a7159d7c22c9fd49acf82ca8ca909a041888c7 Mon Sep 17 00:00:00 2001 From: Maksymilian Knust Date: Thu, 27 Jun 2024 01:05:03 +0200 Subject: [PATCH 4/5] Log seconds and milliseconds --- src/platform/logging/impl/stdio/Logging.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/platform/logging/impl/stdio/Logging.cpp b/src/platform/logging/impl/stdio/Logging.cpp index 99c7cd5e136ccb..af2ee16cd339d6 100644 --- a/src/platform/logging/impl/stdio/Logging.cpp +++ b/src/platform/logging/impl/stdio/Logging.cpp @@ -44,7 +44,7 @@ void LogV(const char * module, uint8_t category, const char * msg, va_list v) #if defined(__APPLE__) || defined(__gnu_linux__) timespec ts; timespec_get(&ts, TIME_UTC); - printf("[%lld] ", static_cast(ts.tv_sec * 1000 + ts.tv_nsec / 1000000)); + printf("[%lld.%ld] ", static_cast(ts.tv_sec), static_cast(ts.tv_nsec / 1000000)); #endif #if defined(__APPLE__) From d8c9c2e767313f2f04ffd49900ae5f7a0ff2f0ab Mon Sep 17 00:00:00 2001 From: Maksymilian Knust Date: Thu, 27 Jun 2024 01:15:11 +0200 Subject: [PATCH 5/5] Update Logging.cpp --- src/platform/logging/impl/stdio/Logging.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/platform/logging/impl/stdio/Logging.cpp b/src/platform/logging/impl/stdio/Logging.cpp index af2ee16cd339d6..26e050f0286f9f 100644 --- a/src/platform/logging/impl/stdio/Logging.cpp +++ b/src/platform/logging/impl/stdio/Logging.cpp @@ -44,7 +44,7 @@ void LogV(const char * module, uint8_t category, const char * msg, va_list v) #if defined(__APPLE__) || defined(__gnu_linux__) timespec ts; timespec_get(&ts, TIME_UTC); - printf("[%lld.%ld] ", static_cast(ts.tv_sec), static_cast(ts.tv_nsec / 1000000)); + printf("[%lld.%03ld] ", static_cast(ts.tv_sec), static_cast(ts.tv_nsec / 1000000)); #endif #if defined(__APPLE__)