From acc1c3fdbdc95cba55cec59000cbd218a630a379 Mon Sep 17 00:00:00 2001 From: gd Date: Tue, 21 Jan 2025 14:01:26 +0200 Subject: [PATCH 1/5] fix: output of command status broken by a misplaced comma in the format arguments introduced by commit b24b3c1 --- src/command/PlayerCommands.cxx | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/command/PlayerCommands.cxx b/src/command/PlayerCommands.cxx index d7486f0537..afbb3d100a 100644 --- a/src/command/PlayerCommands.cxx +++ b/src/command/PlayerCommands.cxx @@ -129,7 +129,7 @@ handle_status(Client &client, [[maybe_unused]] Request args, Response &r) COMMAND_STATUS_PLAYLIST ": {}\n" COMMAND_STATUS_PLAYLIST_LENGTH ": {}\n" COMMAND_STATUS_MIXRAMPDB ": {}\n" - COMMAND_STATUS_STATE ": {}\n", + COMMAND_STATUS_STATE ": {}\n" COMMAND_STATUS_LOADED_PLAYLIST ": {}\n", (unsigned)playlist.GetRepeat(), (unsigned)playlist.GetRandom(), From 1b8ef2403a64b3f20643c03987269a97273bff89 Mon Sep 17 00:00:00 2001 From: gd Date: Wed, 22 Jan 2025 21:13:32 +0200 Subject: [PATCH 2/5] Logging: added seconds to log time string. Time was only in minutes before. Seconds is more useful in analyzing the log for example with issues of timeouts, and reponse times. --- src/LogBackend.cxx | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/LogBackend.cxx b/src/LogBackend.cxx index ce09afb492..f0dffc3a97 100644 --- a/src/LogBackend.cxx +++ b/src/LogBackend.cxx @@ -76,10 +76,10 @@ EnableLogTimestamp() noexcept static const char * log_date() noexcept { - static constexpr size_t LOG_DATE_BUF_SIZE = 16; + static constexpr size_t LOG_DATE_BUF_SIZE = std::char_traits::length("Jan 22 15:43:14 : ") + 1; static char buf[LOG_DATE_BUF_SIZE]; time_t t = time(nullptr); - strftime(buf, LOG_DATE_BUF_SIZE, "%b %d %H:%M : ", localtime(&t)); + strftime(buf, LOG_DATE_BUF_SIZE, "%b %d %H:%M:%S : ", localtime(&t)); return buf; } From 0866d36f9b390a5449338b787769b82823e8cc47 Mon Sep 17 00:00:00 2001 From: gd Date: Wed, 22 Jan 2025 21:15:23 +0200 Subject: [PATCH 3/5] Logging: enable log timestamp to stdout logging When running with stdout output to debug the server or misbehaving clients, it is useful to have the timestamp to detect timing issues and response times. Especially when opening and playing online sources that block the connection thread sometime for a significantly long time that makes the client-server unresponsive and cause timeouts in clients. --- src/LogInit.cxx | 1 + 1 file changed, 1 insertion(+) diff --git a/src/LogInit.cxx b/src/LogInit.cxx index 3203e6e006..7840e09531 100644 --- a/src/LogInit.cxx +++ b/src/LogInit.cxx @@ -130,6 +130,7 @@ log_init(const ConfigData &config, bool verbose, bool use_stdout) if (use_stdout) { out_fd = STDOUT_FILENO; + EnableLogTimestamp(); } else { const auto *param = config.GetParam(ConfigOption::LOG_FILE); if (param == nullptr) { From a837b276594ba78b127f91960c96ce87c96fd2c0 Mon Sep 17 00:00:00 2001 From: gd Date: Wed, 22 Jan 2025 21:23:47 +0200 Subject: [PATCH 4/5] Logging: thread local storage for the static timestamp string buffer in log_date() This function may be called by multiple threads concurrently. But it uses a static buffer for the datetime string which can be written into simultanously by multiple thread. If it is not thread local, for it to corrent it must be assumed that the implementation writing to the buffer never conflicts with itself in a way that may result in a bogus timestamp output. --- src/LogBackend.cxx | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/LogBackend.cxx b/src/LogBackend.cxx index f0dffc3a97..5183777b20 100644 --- a/src/LogBackend.cxx +++ b/src/LogBackend.cxx @@ -77,7 +77,7 @@ static const char * log_date() noexcept { static constexpr size_t LOG_DATE_BUF_SIZE = std::char_traits::length("Jan 22 15:43:14 : ") + 1; - static char buf[LOG_DATE_BUF_SIZE]; + static thread_local char buf[LOG_DATE_BUF_SIZE]; time_t t = time(nullptr); strftime(buf, LOG_DATE_BUF_SIZE, "%b %d %H:%M:%S : ", localtime(&t)); return buf; From 00fbaa547877878b9bdb176894fd59a4d0105c03 Mon Sep 17 00:00:00 2001 From: gd Date: Wed, 22 Jan 2025 21:44:57 +0200 Subject: [PATCH 5/5] Logging: added milli seconds to log time string. Having milliseconds resolution in the log gives more information than just seconds when debugging or analyzing response time issues or effects of changes in server or client code. --- src/LogBackend.cxx | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/LogBackend.cxx b/src/LogBackend.cxx index 5183777b20..026f22b678 100644 --- a/src/LogBackend.cxx +++ b/src/LogBackend.cxx @@ -76,10 +76,13 @@ EnableLogTimestamp() noexcept static const char * log_date() noexcept { - static constexpr size_t LOG_DATE_BUF_SIZE = std::char_traits::length("Jan 22 15:43:14 : ") + 1; + static constexpr size_t LOG_DATE_STR_LEN = std::char_traits::length("Jan 22 15:43:14"); + static constexpr size_t LOG_DATE_BUF_SIZE = LOG_DATE_STR_LEN + std::char_traits::length(".000 : ") + 1; static thread_local char buf[LOG_DATE_BUF_SIZE]; - time_t t = time(nullptr); - strftime(buf, LOG_DATE_BUF_SIZE, "%b %d %H:%M:%S : ", localtime(&t)); + timespec t; + timespec_get(&t, TIME_UTC); + strftime(buf, LOG_DATE_BUF_SIZE, "%b %d %H:%M:%S : ", localtime(&t.tv_sec)); + snprintf(&buf[LOG_DATE_STR_LEN], LOG_DATE_BUF_SIZE - LOG_DATE_STR_LEN, ".%03d : ", int(t.tv_nsec / 1e6)); return buf; }