RCORE-2187 Prefix sync connection log messages with co_id when possible

CHANGELOG.md

@@ -1,8 +1,7 @@
 # NEXT RELEASE
 
 ### Enhancements
-* <New feature description> (PR [#????](https://github.com/realm/realm-core/pull/????))
-* None.
+* Sync log statements now include the app services connection id in their prefix (e.g `Connection[1:<connection id>] Session[1]: log message`) to make correlating sync activity to server logs easier during troubleshooting ((PR #7849)[https://github.com/realm/realm-core/pull/7849]).
 
 ### Fixed
 * <How do the end-user experience this issue? what was the impact?> ([#????](https://github.com/realm/realm-core/issues/????), since v?.?.?)

src/realm/sync/client.cpp

@@ -1832,9 +1832,7 @@ ClientImpl::Connection::Connection(ClientImpl& client, connection_ident_type ide
                                    Optional<std::string> ssl_trust_certificate_path,
                                    std::function<SSLVerifyCallback> ssl_verify_callback,
                                    Optional<ProxyConfig> proxy_config, ReconnectInfo reconnect_info)
-    : logger_ptr{std::make_shared<util::PrefixLogger>(util::LogCategory::session, make_logger_prefix(ident),
-                                                      client.logger_ptr)} // Throws
-    , logger{*logger_ptr}
+    : logger{make_logger(ident, std::nullopt, client.logger.base_logger)} // Throws
     , m_client{client}
     , m_verify_servers_ssl_certificate{verify_servers_ssl_certificate}    // DEPRECATED
     , m_ssl_trust_certificate_path{std::move(ssl_trust_certificate_path)} // DEPRECATED
@@ -1911,9 +1909,13 @@ std::string ClientImpl::Connection::get_http_request_path() const
 }
 
 
-std::string ClientImpl::Connection::make_logger_prefix(connection_ident_type ident)
+std::shared_ptr<util::Logger> ClientImpl::Connection::make_logger(connection_ident_type ident,
+                                                                  std::optional<std::string_view> coid,
+                                                                  std::shared_ptr<util::Logger> base_logger)
 {
-    return util::format("Connection[%1] ", ident);
+    std::string prefix =
+        coid ? util::format("Connection[%1:%2] ", ident, *coid) : util::format("Connection[%1] ", ident);
+    return std::make_shared<util::PrefixLogger>(util::LogCategory::session, std::move(prefix), base_logger);
 }
 
 

src/realm/sync/noinst/client_impl_base.cpp

@@ -137,8 +137,7 @@ bool ClientImpl::decompose_server_url(const std::string& url, ProtocolEnvelope&
 }
 
 ClientImpl::ClientImpl(ClientConfig config)
-    : logger_ptr{std::make_shared<util::CategoryLogger>(util::LogCategory::session, std::move(config.logger))}
-    , logger{*logger_ptr}
+    : logger(std::make_shared<util::CategoryLogger>(util::LogCategory::session, std::move(config.logger)))
     , m_reconnect_mode{config.reconnect_mode}
     , m_connect_timeout{config.connect_timeout}
     , m_connection_linger_time{config.one_connection_per_session ? 0 : config.connection_linger_time}
@@ -1225,6 +1224,14 @@ void Connection::disconnect(const SessionErrorInfo& info)
     m_sessions_enlisted_to_send.clear();
     m_sending = false;
 
+    if (!m_appservices_coid.empty()) {
+        m_appservices_coid.clear();
+        logger.base_logger = make_logger(m_ident, std::nullopt, get_client().logger.base_logger);
+        for (auto& [ident, sess] : m_sessions) {
+            sess->logger.base_logger = Session::make_logger(ident, logger.base_logger);
+        }
+    }
+
     report_connection_state_change(ConnectionState::disconnected, info); // Throws
     initiate_reconnect_wait();                                           // Throws
 }
@@ -1438,36 +1445,35 @@ void Connection::receive_test_command_response(session_ident_type session_ident,
 void Connection::receive_server_log_message(session_ident_type session_ident, util::Logger::Level level,
                                             std::string_view message)
 {
-    std::string prefix;
-    if (REALM_LIKELY(!m_appservices_coid.empty())) {
-        prefix = util::format("Server[%1]", m_appservices_coid);
-    }
-    else {
-        prefix = "Server";
-    }
-
     if (session_ident != 0) {
         if (auto sess = get_session(session_ident)) {
-            sess->logger.log(LogCategory::session, level, "%1 log: %2", prefix, message);
+            sess->logger.log(LogCategory::session, level, "Server log: %1", message);
             return;
         }
 
-        logger.log(util::LogCategory::session, level, "%1 log for unknown session %2: %3", prefix, session_ident,
+        logger.log(util::LogCategory::session, level, "Server log for unknown session %1: %2", session_ident,
                    message);
         return;
     }
 
-    logger.log(level, "%1 log: %2", prefix, message);
+    logger.log(level, "Server log: %1", message);
 }
 
 
 void Connection::receive_appservices_request_id(std::string_view coid)
 {
-    // Only set once per connection
-    if (!coid.empty() && m_appservices_coid.empty()) {
-        m_appservices_coid = coid;
-        logger.log(util::LogCategory::session, util::LogCategory::Level::info,
-                   "Connected to app services with request id: \"%1\"", m_appservices_coid);
+    if (coid.empty() || !m_appservices_coid.empty()) {
+        return;
+    }
+    m_appservices_coid = coid;
+    logger.log(util::LogCategory::session, util::LogCategory::Level::info,
+               "Connected to app services with request id: \"%1\". Further log entries for this connection will be "
+               "prefixed with \"Connection[%2:%1]\" instead of \"Connection[%2]\"",
+               m_appservices_coid, m_ident);
+    logger.base_logger = make_logger(m_ident, m_appservices_coid, get_client().logger.base_logger);
+
+    for (auto& [ident, sess] : m_sessions) {
+        sess->logger.base_logger = Session::make_logger(ident, logger.base_logger);
     }
 }
 
@@ -1667,15 +1673,14 @@ Session::~Session()
 }
 
 
-std::string Session::make_logger_prefix(session_ident_type ident)
+std::shared_ptr<util::Logger> Session::make_logger(session_ident_type ident,
+                                                   std::shared_ptr<util::Logger> base_logger)
 {
-    std::ostringstream out;
-    out.imbue(std::locale::classic());
-    out << "Session[" << ident << "]: "; // Throws
-    return out.str();                    // Throws
+    auto prefix = util::format("Session[%1]: ", ident);
+    return std::make_shared<util::PrefixLogger>(util::LogCategory::session, std::move(prefix),
+                                                std::move(base_logger));
 }
 
-
 void Session::activate()
 {
     REALM_ASSERT_EX(m_state == Unactivated, m_state);

src/realm/sync/noinst/client_impl_base.hpp

@@ -195,8 +195,23 @@ class ClientImpl {
     static constexpr milliseconds_type default_pong_keepalive_timeout = 120000; // 2 minutes
     static constexpr milliseconds_type default_fast_reconnect_limit = 60000;    // 1 minute
 
-    const std::shared_ptr<util::Logger> logger_ptr;
-    util::Logger& logger;
+    class ForwardingLogger : public util::Logger {
+    public:
+        ForwardingLogger(std::shared_ptr<util::Logger> logger)
+            : Logger(logger->get_category(), *logger)
+            , base_logger(std::move(logger))
+        {
+        }
+
+        void do_log(const util::LogCategory& cat, Level level, const std::string& msg) final
+        {
+            Logger::do_log(*base_logger, cat, level, msg);
+        }
+
+        std::shared_ptr<util::Logger> base_logger;
+    };
+
+    ForwardingLogger logger;
 
     ClientImpl(ClientConfig);
     ~ClientImpl();
@@ -391,8 +406,7 @@ class ClientImpl::Connection {
     using ReconnectInfo = ClientImpl::ReconnectInfo;
     using DownloadMessage = ClientProtocol::DownloadMessage;
 
-    std::shared_ptr<util::Logger> logger_ptr;
-    util::Logger& logger;
+    ForwardingLogger logger;
 
     ClientImpl& get_client() noexcept;
     ReconnectInfo get_reconnect_info() const noexcept;
@@ -573,7 +587,9 @@ class ClientImpl::Connection {
     Session* find_and_validate_session(session_ident_type session_ident, std::string_view message) noexcept;
     static bool was_voluntary(ConnectionTerminationReason) noexcept;
 
-    static std::string make_logger_prefix(connection_ident_type);
+    static std::shared_ptr<util::Logger> make_logger(connection_ident_type ident,
+                                                     std::optional<std::string_view> coid,
+                                                     std::shared_ptr<util::Logger> base_logger);
 
     void report_connection_state_change(ConnectionState, util::Optional<SessionErrorInfo> error_info = util::none);
 
@@ -693,7 +709,6 @@ class ClientImpl::Connection {
     std::string m_signed_access_token;
 };
 
-
 /// A synchronization session between a local and a remote Realm file.
 ///
 /// All use of session objects, including construction and destruction, must
@@ -703,8 +718,7 @@ class ClientImpl::Session {
     using ReceivedChangesets = ClientProtocol::ReceivedChangesets;
     using DownloadMessage = ClientProtocol::DownloadMessage;
 
-    std::shared_ptr<util::Logger> logger_ptr;
-    util::Logger& logger;
+    ForwardingLogger logger;
 
     ClientImpl& get_client() noexcept;
     Connection& get_connection() noexcept;
@@ -1058,7 +1072,7 @@ class ClientImpl::Session {
     request_ident_type m_last_pending_test_command_ident = 0;
     std::list<PendingTestCommand> m_pending_test_commands;
 
-    static std::string make_logger_prefix(session_ident_type);
+    static std::shared_ptr<util::Logger> make_logger(session_ident_type, std::shared_ptr<util::Logger> base_logger);
 
     Session(SessionWrapper& wrapper, Connection&, session_ident_type);
 
@@ -1341,9 +1355,7 @@ inline ClientImpl::Session::Session(SessionWrapper& wrapper, Connection& conn)
 }
 
 inline ClientImpl::Session::Session(SessionWrapper& wrapper, Connection& conn, session_ident_type ident)
-    : logger_ptr{std::make_shared<util::PrefixLogger>(util::LogCategory::session, make_logger_prefix(ident),
-                                                      conn.logger_ptr)} // Throws
-    , logger{*logger_ptr}
+    : logger{make_logger(ident, conn.logger.base_logger)} // Throws
     , m_conn{conn}
     , m_ident{ident}
     , m_try_again_delay_info(conn.get_client().m_reconnect_backoff_info, conn.get_client().get_random())

src/realm/util/logger.hpp

@@ -245,6 +245,11 @@ class Logger {
         set_level_threshold(m_category, level);
     }
 
+    const LogCategory& get_category() const noexcept
+    {
+        return m_category;
+    }
+
     // Set threshold level for the specific category
     void set_level_threshold(std::string_view cat_name, Level level) noexcept
     {