fix: accurate timestamp in daemon logs (#7009)

* fix: accurate timestamp in daemon logs

* fix: gtk build errors

* fixup! fix: gtk build errors

* code review: use system_clock typedefs

* code review: use the full buffer for string view

* fixup! fix: accurate timestamp in daemon logs

* code review: limit exposure of `using`

daemon/daemon.cc

@@ -5,6 +5,7 @@
 
 #include <array>
 #include <cerrno>
+#include <chrono>
 #include <cstdio> /* printf */
 #include <iostream>
 #include <iterator> /* std::back_inserter */
@@ -269,6 +270,7 @@ auto onFileAdded(tr_session* session, std::string_view dirname, std::string_view
 
 void printMessage(
     FILE* ostream,
+    std::chrono::system_clock::time_point now,
     tr_log_level level,
     std::string_view name,
     std::string_view message,
@@ -288,9 +290,9 @@ void printMessage(
 
     if (ostream != nullptr)
     {
-        auto timestr = std::array<char, 64>{};
+        auto buf = std::array<char, 64>{};
-        tr_logGetTimeStr(std::data(timestr), std::size(timestr));
+        auto const timestr = tr_logGetTimeStr(now, std::data(buf), std::size(buf));
-        fmt::print(ostream, "[{:s}] {:s} {:s}\n", std::data(timestr), levelName(level), out.c_str());
+        fmt::print(ostream, "[{:s}] {:s} {:s}\n", timestr, levelName(level), out.c_str());
     }
 
 #ifdef HAVE_SYSLOG
@@ -329,13 +331,24 @@ void printMessage(
 #endif
 }
 
+void printMessage(
+    FILE* ostream,
+    tr_log_level level,
+    std::string_view name,
+    std::string_view message,
+    std::string_view filename,
+    long line)
+{
+    printMessage(ostream, std::chrono::system_clock::now(), level, name, message, filename, line);
+}
+
 void pumpLogMessages(FILE* log_stream)
 {
     tr_log_message* list = tr_logGetQueue();
 
     for (tr_log_message const* l = list; l != nullptr; l = l->next)
     {
-        printMessage(log_stream, l->level, l->name, l->message, l->file, l->line);
+        printMessage(log_stream, l->when, l->level, l->name, l->message, l->file, l->line);
     }
 
     // two reasons to not flush stderr:

gtk/MessageLogWindow.cc

@@ -37,6 +37,7 @@
 #include <fmt/ostream.h>
 
 #include <array>
+#include <chrono>
 #include <fstream>
 #include <memory>
 #include <utility>
@@ -201,11 +202,12 @@ void MessageLogWindow::Impl::level_combo_changed_cb(Gtk::ComboBox* combo_box)
 
 namespace
 {
+using std::chrono::system_clock;
 
 /* similar to asctime, but is utf8-clean */
-Glib::ustring gtr_asctime(time_t t)
+Glib::ustring gtr_asctime(system_clock::time_point t)
 {
-    return Glib::DateTime::create_now_local(t).format("%a %b %e %T %Y"); /* ctime equiv */
+    return Glib::DateTime::create_now_local(system_clock::to_time_t(t)).format("%a %b %e %T %Y"); /* ctime equiv */
 }
 
 } // namespace
@@ -324,7 +326,7 @@ void renderText(
 void renderTime(Gtk::CellRendererText* renderer, Gtk::TreeModel::const_iterator const& iter)
 {
     auto const* const node = iter->get_value(message_log_cols.tr_msg);
-    renderer->property_text() = Glib::DateTime::create_now_local(node->when).format("%T");
+    renderer->property_text() = Glib::DateTime::create_now_local(std::chrono::system_clock::to_time_t(node->when)).format("%T");
     setForegroundColor(renderer, node->level);
 }
 

libtransmission/log.cc

@@ -111,7 +111,7 @@ void logAddImpl(
     {
         auto* const newmsg = new tr_log_message{};
         newmsg->level = level;
-        newmsg->when = tr_time();
+        newmsg->when = std::chrono::system_clock::now();
         newmsg->message = std::move(msg);
         newmsg->file = file;
         newmsg->line = line;
@@ -133,16 +133,16 @@ void logAddImpl(
     }
     else
     {
-        auto timestr = std::array<char, 64U>{};
+        auto buf = std::array<char, 64U>{};
-        tr_logGetTimeStr(std::data(timestr), std::size(timestr));
+        auto const timestr = tr_logGetTimeStr(std::data(buf), std::size(buf));
 
         if (std::empty(name))
         {
-            fmt::print(stderr, "[{:s}] {:s}\n", std::data(timestr), msg);
+            fmt::print(stderr, "[{:s}] {:s}\n", timestr, msg);
         }
         else
         {
-            fmt::print("[{:s}] {:s}: {:s}\n", std::data(timestr), name, msg);
+            fmt::print("[{:s}] {:s}: {:s}\n", timestr, name, msg);
         }
     }
 #endif
@@ -194,19 +194,23 @@ void tr_logFreeQueue(tr_log_message* freeme)
 
 // ---
 
-char* tr_logGetTimeStr(char* buf, size_t buflen)
+std::string_view tr_logGetTimeStr(std::chrono::system_clock::time_point now, char* buf, size_t buflen)
 {
-    auto const a = std::chrono::system_clock::now();
+    auto const now_tm = fmt::localtime(std::chrono::system_clock::to_time_t(now));
-    auto const a_tm = fmt::localtime(std::chrono::system_clock::to_time_t(a));
+    auto const subseconds = now - std::chrono::time_point_cast<std::chrono::seconds>(now);
-    auto const subseconds = a - std::chrono::time_point_cast<std::chrono::seconds>(a);
     auto const [out, len] = fmt::format_to_n(
         buf,
-        buflen - 1,
+        buflen,
         "{0:%FT%T.}{1:0>3%Q}{0:%z}",
-        a_tm,
+        now_tm,
         std::chrono::duration_cast<std::chrono::milliseconds>(subseconds));
-    *out = '\0';
+    return { buf, len };
-    return buf;
+}
+
+std::string_view tr_logGetTimeStr(char* buf, size_t buflen)
+{
+    auto const a = std::chrono::system_clock::now();
+    return tr_logGetTimeStr(a, buf, buflen);
 }
 
 void tr_logAddMessage(char const* file, long line, tr_log_level level, std::string&& msg, std::string_view name)

libtransmission/log.h

@@ -5,6 +5,7 @@
 
 #pragma once
 
+#include <chrono>
 #include <cstddef> // size_t
 #include <ctime>
 #include <optional>
@@ -53,7 +54,7 @@ struct tr_log_message
     long line;
 
     // when the message was generated
-    time_t when;
+    std::chrono::system_clock::time_point when;
 
     // torrent name or code module name associated with the message
     std::string name;
@@ -110,4 +111,5 @@ void tr_logAddMessage(
 
 // ---
 
-char* tr_logGetTimeStr(char* buf, size_t buflen);
+std::string_view tr_logGetTimeStr(std::chrono::system_clock::time_point now, char* buf, size_t buflen);
+std::string_view tr_logGetTimeStr(char* buf, size_t buflen);

macosx/MessageWindowController.mm

@@ -250,9 +250,10 @@ static NSTimeInterval const kUpdateSeconds = 0.75;
         auto const file_string = std::string{ currentMessage->file };
         NSString* file = [(@(file_string.c_str())).lastPathComponent stringByAppendingFormat:@":%ld", currentMessage->line];
 
+        auto const secs_since_1970 = std::chrono::system_clock::to_time_t(currentMessage->when);
         NSDictionary* message = @{
             @"Message" : @(currentMessage->message.c_str()),
-            @"Date" : [NSDate dateWithTimeIntervalSince1970:currentMessage->when],
+            @"Date" : [NSDate dateWithTimeIntervalSince1970:secs_since_1970],
             @"Index" : @(currentIndex++), //more accurate when sorting by date
             @"Level" : @(currentMessage->level),
             @"Name" : name,