RCORE-2187 Prefix sync connection log messages with co_id when possib…

…le (#7849)

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
     {

test/object-store/sync/app.cpp

@@ -3282,6 +3282,51 @@ TEST_CASE("app: sync integration", "[sync][pbs][app][baas]") {
     }
 }
 
+TEST_CASE("app: sync logs contain baas coid", "[sync][app][baas]") {
+    class InMemoryLogger : public util::Logger {
+    public:
+        void do_log(const util::LogCategory& cat, Level level, const std::string& msg) final
+        {
+            auto formatted_line = util::format("%1 %2 %3", cat.get_name(), level, msg);
+            std::lock_guard lk(mtx);
+            log_messages.emplace_back(std::move(formatted_line));
+        }
+
+        std::vector<std::string> get_log_messages()
+        {
+            std::lock_guard lk(mtx);
+            std::vector<std::string> ret;
+            std::swap(ret, log_messages);
+            return ret;
+        }
+
+        std::mutex mtx;
+        std::vector<std::string> log_messages;
+    };
+
+    auto in_mem_logger = std::make_shared<InMemoryLogger>();
+    TestAppSession app_session(get_runtime_app_session(), nullptr, DeleteApp{false}, ReconnectMode::normal, nullptr,
+                               in_mem_logger);
+
+    const auto partition = random_string(100);
+    SyncTestFile config(app_session.app()->current_user(), partition, util::none);
+    auto realm = successfully_async_open_realm(config);
+    auto sync_session = realm->sync_session();
+    auto coid = SyncSession::OnlyForTesting::get_appservices_connection_id(*sync_session);
+
+    auto transition_log_msg =
+        util::format("Connection[1] Connected to app services with request id: \"%1\". Further log entries for this "
+                     "connection will be prefixed with \"Connection[1:%1]\" instead of \"Connection[1]\"",
+                     coid);
+    auto bind_send_msg = util::format("Connection[1:%1] Session[1]: Sending: BIND", coid);
+    auto ping_send_msg = util::format("Connection[1:%1] Will emit a ping in", coid);
+
+    auto log_messages = in_mem_logger->get_log_messages();
+    REQUIRE_THAT(log_messages, AnyMatch(ContainsSubstring(transition_log_msg)));
+    REQUIRE_THAT(log_messages, AnyMatch(ContainsSubstring(bind_send_msg)));
+    REQUIRE_THAT(log_messages, AnyMatch(ContainsSubstring(ping_send_msg)));
+}
+
 
 TEST_CASE("app: trailing slash in base url", "[sync][app]") {
     auto logger = util::Logger::get_default_logger();

test/object-store/util/test_file.cpp

@@ -336,7 +336,8 @@ TestAppSession::TestAppSession()
 TestAppSession::TestAppSession(AppSession session,
                                std::shared_ptr<realm::app::GenericNetworkTransport> custom_transport,
                                DeleteApp delete_app, ReconnectMode reconnect_mode,
-                               std::shared_ptr<realm::sync::SyncSocketProvider> custom_socket_provider)
+                               std::shared_ptr<realm::sync::SyncSocketProvider> custom_socket_provider,
+                               std::shared_ptr<realm::util::Logger> logger)
     : m_app_session(std::make_unique<AppSession>(session))
     , m_base_file_path(util::make_temp_dir() + random_string(10))
     , m_delete_app(delete_app)
@@ -356,6 +357,11 @@ TestAppSession::TestAppSession(AppSession session,
     // connection is kept open for reuse. In tests, we want to shut
     // down sync clients immediately.
     app_config.sync_client_config.timeouts.connection_linger_time = 0;
+    if (logger) {
+        app_config.sync_client_config.logger_factory = [logger](util::Logger::Level) {
+            return logger;
+        };
+    }
 
     m_app = app::App::get_app(app::App::CacheMode::Disabled, app_config);
 

test/object-store/util/test_file.hpp

@@ -326,7 +326,8 @@ class TestAppSession {
     TestAppSession();
     TestAppSession(realm::AppSession, std::shared_ptr<realm::app::GenericNetworkTransport> = nullptr,
                    DeleteApp = true, realm::ReconnectMode reconnect_mode = realm::ReconnectMode::normal,
-                   std::shared_ptr<realm::sync::SyncSocketProvider> custom_socket_provider = nullptr);
+                   std::shared_ptr<realm::sync::SyncSocketProvider> custom_socket_provider = nullptr,
+                   std::shared_ptr<realm::util::Logger> logger = nullptr);
     ~TestAppSession();
 
     std::shared_ptr<realm::app::App> app() const noexcept