Support logging messages from the server #6476

jbreams · 2023-04-05T21:35:58Z

What, How & Why?

Server log messages are going to be added to server protocol version 10 with the new session bind reason value. This code implements the receiving of log_message protocol messages from the server and prints them using the log level provided in the message. The connection id for the server will no longer be extracted from the websocket header and will be provided to the sync client as a log message with the "co_id" value when the websocket connection is first established. The websocket support for retrieving the request id value from the Websocket ACCEPT response HTTP headers added in #6143 will be removed once the server is sending the request id within server log messages.

log_message protocol messages use the following format:

log_message <session_ident> <logmsg_json_data_size>\n<logmsg_json_data>

<session_ident> - The ident for the session sending the message or 0 if the message is being sent
                  for the connection
<logmsg_json_data> - A json structure containing the following keys:
  * "level" - The log output level as a string {"trace", "debug", "detail", "info", "warn", "error", "fatal"}
              Defaults to "debug" if string is empty or not provided.
  * "msg" - The log message to be output by the client at the specified log level. Nothing will be
            printed if this value is empty or not provided.
  * "co_id" - The appservices request id value as a string. This value is optional, but cannot be empty
              if it is provided.

The SyncServer was also updated to send a log message from connections and sessions to verify the operation of the receiving log_message messages. It will also send the appservices request id when the connection is established. This support is enabled if the client is using server protocol version 10 or greater.

Fixes #6801

☑️ ToDos

📝 Changelog update
🚦 Tests (or not relevant)
~~[ ] C-API, if public C++ API changed.~~

…log_messages

danieltabacaru · 2023-08-17T06:04:21Z

src/realm/sync/noinst/client_impl_base.cpp

    m_state = ConnectionState::connected;

-    // TODO(RCORE-1380) get this information in-band rather than from the websocket.
-    if (auto coid = m_websocket->get_appservices_request_id(); !coid.empty()) {


you should remove this method since it's only used here

We can remove this function eventually, once the new server version is released.

danieltabacaru · 2023-08-17T06:05:58Z

src/realm/sync/noinst/client_impl_base.cpp

+            return;
+        }
+
+        logger.log(level, "Server log message for unknown session %1: %2", session_ident, message);


you need a return after this instruction

danieltabacaru · 2023-08-17T06:22:33Z

src/realm/sync/noinst/protocol_codec.hpp

+                                        e.what());
+                }
+
+                static constexpr std::array<std::pair<std::string_view, util::Logger::Level>, 7> name_to_level = {


can't this be an unordered_map so you can easily do the lookup below?

Sure, I can make it a map

danieltabacaru · 2023-08-17T07:50:52Z

src/realm/sync/noinst/server/server.cpp

            // No sessions were enlisted to send
            if (REALM_LIKELY(!m_is_closing))
-                return; // Nothing more to do right now
+                break; // Check to see if there are any log messages to go out


we can keep this the way it is if we move sending the log messages before the for loop.

I wanted to give priority to any other messages that need to be sent before the log messages.

src/realm/sync/noinst/client_impl_base.cpp

danieltabacaru · 2023-08-17T20:08:20Z

src/realm/sync/noinst/client_impl_base.cpp

                    logger.detail("Negotiated protocol version: %1", value_2);
+                    // Grab the connection ID from the websocket if the protocol version is less than 10,
+                    // otherwise, this value will come in a server log message
+                    if (value_2 < 10) {


Is this a temporary thing?

It can be - since baas is not yet at protocol v10, I wanted to make sure things still worked the same until it is updated.
I have a similar check in the Sync Server for sending log messages.

kmorkos · 2023-08-17T20:01:16Z

src/realm/sync/noinst/client_impl_base.cpp

+                    // Grab the connection ID from the websocket if the protocol version is less than 10,
+                    // otherwise, this value will come in a server log message
+                    if (value_2 < 10) {
+                        receive_appservices_coid(m_websocket->get_appservices_request_id());
+                    }


hm, can we just always do this for now? otherwise this would block @yaseenmongo's work on the server change to start sending these, and that has not been prioritized yet.

Do you mean the protocol update to v10 has been delayed?
This is here to retain the previous functionality until the server protocol is updated to v10.
Or is the co_id not going to be sent until later, even though the new bind format and server log messages will be supported sooner?

Or is the co_id not going to be sent until later, even though the new bind format and server log messages will be supported sooner?

right - the new bind format is being supported first which will involve the protocol version bump on the server (blocker for the breaking changes project). support for the log messages will come later (but that should does not need to block merging this client-side support for it)

src/realm/sync/noinst/protocol_codec.hpp

kmorkos · 2023-08-17T20:14:11Z

src/realm/sync/noinst/protocol_codec.hpp

+            {"trace", util::Logger::Level::trace},
+        };
+
+        // connection id (co_id) is optional and level and msg are optional if a co_id is provided


i think we can loosen these invariants for simplicity

the server always has access to co_id, so it will likely always include it
we can make level optional and always default to debug/info (although the server would likely always include this as well)
and msg can also be "optional" and default to <no message> or something if the key is not provided (again, this would likely never happen)

lmk what you think

I think the original "strict" checking was to find any malformed log messages from the server so they can be fixed.
We can loosen this checking, with a default level of Debug and nothing will be printed if the message is missing or empty.

danieltabacaru · 2023-08-18T07:23:02Z

src/realm/sync/noinst/server/server.cpp

+    void send_log_message(util::Logger::Level level, const std::string&& message)
+    {
+        // Clients with protocol version less than 10 do not support log messages
+        if (m_connection.get_client_protocol_version() < 10) {


nit: you can create a const for it

danieltabacaru · 2023-08-18T10:50:22Z

src/realm/sync/noinst/client_impl_base.cpp

+                    // For now, grab the connection ID from the websocket if it supports it. In the future, the server
+                    // will provide the appservices connection ID via a log message.
+                    // TODO: Remove once the server starts sending the connection ID
+                    receive_appservices_request_id(m_websocket->get_appservices_request_id());


get_appservices_request_id() didn't seem to always have a value at this point previously

is that why we have the checks in receive_server_log_message()?

The flow in websocket_handshake_completion_handler() will extract it from the headers before the call to websocket_connected_handler()

The checks in receive_server_log_message() is for when the server is providing the request_id and a log message is printed before it has sent this value. If it is always including the request_id in every log message, the checks aren't really needed. Also, custom platform networking implementations may not be able to provide this value, so it could be blank.

danieltabacaru · 2023-08-18T11:30:35Z

src/realm/sync/noinst/protocol_codec.hpp

+        }
+
+        std::string_view log_level;
+        bool has_level = false;


(why) is this optional?

Kiro had suggested it could default to a value (debug) if it wasn't provided.

danieltabacaru · 2023-08-18T11:31:55Z

src/realm/sync/noinst/protocol_codec.hpp

+            return;
+        }
+
+        try {


this is a bit of an overkill, you can just use std::unordered_map::find().

danieltabacaru · 2023-08-18T11:38:21Z

src/realm/sync/noinst/server/server.cpp

+        {
+            std::lock_guard log_guard(m_log_mutex);
+            m_log_messages.push(std::move(log_msg));
+            m_send_trigger->trigger();


I guess the trigger does not need be under lock.

…log_messages

danieltabacaru

LGTM. protocol.md should be updated with this new message.

…log_messages

danieltabacaru · 2023-08-21T15:39:53Z

doc/protocol.md

+
+The body of the message is required and will be in JSON format with the following keys
+currently supported:
+    - `co_id` is a string value that provides the appservices request/connection id for the


I wonder if this should be part of the header cc @kmorkos

hmm, i think if the client is considering it optional then we should keep it in the json blob

I think it's up to the server if it's optional or not.

i was going based on the docstring here. let's keep it optional just in case for forward compatibility

OK - I'll keep it as part of the JSON so it can be optional (the client really only needs to receive it once during a connection, since it will be cached when first received).

danieltabacaru · 2023-08-21T15:41:37Z

CHANGELOG.md

 ### Enhancements
 * <New feature description> (PR [#????](https://github.com/realm/realm-core/pull/????))
-* None.
+* Added support for server log messages that are enabled by server protocol version 10. Appservices request id will be provided in a server log message in a future server release. ([PR #6476](https://github.com/realm/realm-core/pull/6476))


sync protocol version

Support logging messages from the server

736304b

cla-bot bot added the cla: yes label Apr 5, 2023

github-actions bot assigned jbreams Apr 5, 2023

jbreams added 3 commits April 5, 2023 17:58

use json body

609df4c

remove leftover test

85902f6

make it constexpr

3487794

sync-by-unito bot mentioned this pull request Aug 11, 2023

Add mechanism for server to send log messages to the client that do not interrupt the sync session #6801

Closed

kmorkos mentioned this pull request Aug 16, 2023

Update BIND message with reason on what a session is used for #6902

Merged

1 task

Michael Wilkerson-Barker added 3 commits August 16, 2023 23:26

Merge branch 'master' of github.com:realm/realm-core into jbr/server_…

96841da

…log_messages

Updated log message output for server log messages

8869057

Added sending server log messages to Sync Server

eb82a28

michael-wb self-assigned this Aug 17, 2023

michael-wb marked this pull request as ready for review August 17, 2023 05:08

michael-wb requested review from danieltabacaru and kmorkos August 17, 2023 05:22

danieltabacaru reviewed Aug 17, 2023

View reviewed changes

kmorkos reviewed Aug 17, 2023

View reviewed changes

src/realm/sync/noinst/client_impl_base.cpp Show resolved Hide resolved

Michael Wilkerson-Barker added 3 commits August 17, 2023 13:49

Added 'co_id' field support to server log messages

cd4a53c

Updates from review

89c1076

Updated changelog

e0860ae

michael-wb requested review from danieltabacaru and kmorkos August 17, 2023 18:53

Fixed codefactor complaint

4aaad65

danieltabacaru reviewed Aug 17, 2023

View reviewed changes

kmorkos reviewed Aug 17, 2023

View reviewed changes

keep websocket request id for now, loosen log message format checks

01c806b

danieltabacaru reviewed Aug 18, 2023

View reviewed changes

Michael Wilkerson-Barker added 3 commits August 18, 2023 13:44

Updates from review

42b6226

Merge branch 'master' of github.com:realm/realm-core into jbr/server_…

4fb4684

…log_messages

Updated changelog after release

1d47a39

michael-wb requested review from danieltabacaru and kmorkos August 18, 2023 18:09

kmorkos approved these changes Aug 18, 2023

View reviewed changes

danieltabacaru approved these changes Aug 18, 2023

View reviewed changes

Michael Wilkerson-Barker added 2 commits August 21, 2023 10:47

Merge branch 'master' of github.com:realm/realm-core into jbr/server_…

0ad780e

…log_messages

Updated protocol.md with new log_message message format

490eeb8

danieltabacaru reviewed Aug 21, 2023

View reviewed changes

Michael Wilkerson-Barker added 2 commits August 21, 2023 16:50

Updated changelog message

3e3f7aa

Updated protocol version desc; sync server updates

e6a478a

michael-wb merged commit 6596065 into master Aug 22, 2023

michael-wb deleted the jbr/server_log_messages branch August 22, 2023 15:00

github-actions bot locked as resolved and limited conversation to collaborators Mar 21, 2024

+                          return;
+                      }
+                      try {

Support logging messages from the server #6476

Support logging messages from the server #6476

Uh oh!

Conversation

jbreams commented Apr 5, 2023 • edited by michael-wb Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What, How & Why?

☑️ ToDos

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

michael-wb Aug 17, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

michael-wb Aug 17, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

danieltabacaru Aug 18, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

danieltabacaru left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

jbreams commented Apr 5, 2023 •

edited by michael-wb

Loading

michael-wb Aug 17, 2023 •

edited

Loading

michael-wb Aug 17, 2023 •

edited

Loading

danieltabacaru Aug 18, 2023 •

edited

Loading