Handle badchangeset error when printing changeset contents in debug (#…

…6921)

* catch badchangeset error when debug printing changeset contents
* Updated changelog
* Fixed race condition in  tests
* Updated ssh/scp timeout to 60 secs

CHANGELOG.md

@@ -19,6 +19,7 @@
 ### Internals
 * Add information about the reason a synchronization session is used for to flexible sync client BIND message. ([PR #6902](https://github.com/realm/realm-core/pull/6902))
 * Sync protocol version bumped to 10. ([PR #6902](https://github.com/realm/realm-core/pull/6902))
+* Handle badchangeset error when printing changeset contents in debug. ([PR #6921](https://github.com/realm/realm-core/pull/6921))
 
 ----------------------------------------------
 

evergreen/config.yml

@@ -297,7 +297,7 @@ functions:
         export BAAS_HOST_NAME
 
         ssh_user="$(printf "ubuntu@%s" "$BAAS_HOST_NAME")"
-        ssh_options="-o ForwardAgent=yes -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o ConnectTimeout=10 -i .baas_ssh_key"
+        ssh_options="-o ForwardAgent=yes -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o ConnectTimeout=60 -i .baas_ssh_key"
 
         # Copy the baas_server.log and mongod.log files from the remote baas host
         REMOTE_PATH=/data/baas-remote/baas-work-dir

evergreen/setup_baas_host_local.sh

@@ -119,7 +119,7 @@ if [[ -f ~/.ssh/id_rsa ]]; then
     ssh-add ~/.ssh/id_rsa
 fi
 ssh-add "${BAAS_HOST_KEY}"
-SSH_OPTIONS=(-o ForwardAgent=yes -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o ConnectTimeout=10 -i "${BAAS_HOST_KEY}")
+SSH_OPTIONS=(-o ForwardAgent=yes -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -i "${BAAS_HOST_KEY}")
 
 echo "running ssh with ${SSH_OPTIONS[*]}"
 
@@ -131,7 +131,7 @@ CONNECT_COUNT=2
 # Check for remote connectivity - try to connect twice to verify server is "really" ready
 # The tests failed one time due to this ssh command passing, but the next scp command failed
 while [[ ${CONNECT_COUNT} -gt 0 ]]; do
-    until ssh "${SSH_OPTIONS[@]}" "${SSH_USER}" "echo -n 'hello from '; hostname" ; do
+    until ssh "${SSH_OPTIONS[@]}" -o ConnectTimeout=10 "${SSH_USER}" "echo -n 'hello from '; hostname" ; do
         if [[ ${WAIT_COUNTER} -ge ${RETRY_COUNT} ]] ; then
             secs_spent_waiting=$(($(date -u +'%s') - WAIT_START))
             echo "Timed out after waiting ${secs_spent_waiting} seconds for host ${BAAS_HOST_NAME} to start"
@@ -148,11 +148,11 @@ done
 
 echo "Transferring setup scripts to ${SSH_USER}:${FILE_DEST_DIR}"
 # Copy the baas host vars script to the baas remote host
-scp "${SSH_OPTIONS[@]}" "${BAAS_HOST_VARS}" "${SSH_USER}:${FILE_DEST_DIR}/"
+scp "${SSH_OPTIONS[@]}" -o ConnectTimeout=60 "${BAAS_HOST_VARS}" "${SSH_USER}:${FILE_DEST_DIR}/"
 # Copy the current host and baas scripts from the working copy of realm-core
 # This ensures they have the latest copy, esp when running evergreen patches
-scp "${SSH_OPTIONS[@]}" "${EVERGREEN_PATH}/setup_baas_host.sh" "${SSH_USER}:${FILE_DEST_DIR}/"
-scp "${SSH_OPTIONS[@]}" "${EVERGREEN_PATH}/install_baas.sh" "${SSH_USER}:${FILE_DEST_DIR}/"
+scp "${SSH_OPTIONS[@]}" -o ConnectTimeout=60 "${EVERGREEN_PATH}/setup_baas_host.sh" "${SSH_USER}:${FILE_DEST_DIR}/"
+scp "${SSH_OPTIONS[@]}" -o ConnectTimeout=60 "${EVERGREEN_PATH}/install_baas.sh" "${SSH_USER}:${FILE_DEST_DIR}/"
 
 echo "Starting remote baas with branch/commit: '${BAAS_BRANCH}'"
 SETUP_BAAS_OPTS=()
@@ -166,4 +166,5 @@ fi
 # Run the setup baas host script and provide the location of the baas host vars script
 # Also sets up a forward tunnel for port 9090 through the ssh connection to the baas remote host
 echo "Running setup script (with forward tunnel to 127.0.0.1:9090)"
-ssh "${SSH_OPTIONS[@]}" -L 9090:127.0.0.1:9090 "${SSH_USER}" "${FILE_DEST_DIR}/setup_baas_host.sh" "${SETUP_BAAS_OPTS[@]}" "${FILE_DEST_DIR}/baas_host_vars.sh"
+ssh "${SSH_OPTIONS[@]}" -o ConnectTimeout=60 -L 9090:127.0.0.1:9090 "${SSH_USER}" \
+"${FILE_DEST_DIR}/setup_baas_host.sh" "${SETUP_BAAS_OPTS[@]}" "${FILE_DEST_DIR}/baas_host_vars.sh"

src/realm/sync/changeset_parser.cpp

@@ -83,7 +83,7 @@ struct State {
 
     BinaryData read_buffer(size_t size);
 
-    REALM_NORETURN void parser_error(const char* complaint); // Throws
+    REALM_NORETURN void parser_error(std::string_view complaint); // Throws
     REALM_NORETURN void parser_error()
     {
         parser_error("Bad input");
@@ -333,11 +333,11 @@ void State::parse_one()
     if (t == InstrTypeInternString) {
         uint32_t index = read_int<uint32_t>();
         if (index != m_intern_strings.size()) {
-            parser_error("Unexpected intern index");
+            parser_error(util::format("Unexpected intern index: %1", index));
         }
         StringData str = read_string();
         if (!m_intern_strings.insert(str).second) {
-            parser_error("Unexpected intern string");
+            parser_error(util::format("Unexpected intern string: %1", str));
         }
         StringBufferRange range = m_handler.add_string_range(str);
         m_handler.set_intern_string(index, range);
@@ -356,7 +356,8 @@ void State::parse_one()
                     spec.pk_field = read_intern_string();
                     spec.pk_type = read_payload_type();
                     if (!is_valid_key_type(spec.pk_type)) {
-                        parser_error("Invalid primary key type in AddTable");
+                        parser_error(util::format("Invalid primary key type in AddTable: %1",
+                                                  static_cast<uint8_t>(spec.pk_type)));
                     }
                     spec.pk_nullable = read_bool();
                     spec.is_asymmetric = (table_type == Table::Type::TopLevelAsymmetric);
@@ -368,7 +369,7 @@ void State::parse_one()
                     break;
                 }
                 default:
-                    parser_error("AddTable: unknown table type");
+                    parser_error(util::format("AddTable: unknown table type: %1", table_type));
             }
             m_handler(instr);
             return;
@@ -498,7 +499,7 @@ void State::parse_one()
         }
     }
 
-    parser_error("unknown instruction");
+    parser_error(util::format("Unknown instruction type: %1", t));
 }
 
 
@@ -663,9 +664,9 @@ BinaryData State::read_buffer(size_t size)
     return BinaryData(m_buffer.data(), size);
 }
 
-void State::parser_error(const char* complaints)
+void State::parser_error(std::string_view complaints)
 {
-    throw BadChangesetError{complaints};
+    throw BadChangesetError{std::string(complaints)};
 }
 
 } // anonymous namespace

src/realm/sync/noinst/client_impl_base.cpp

@@ -2053,10 +2053,15 @@ void Session::send_upload_message()
 #if REALM_DEBUG
             ChunkedBinaryInputStream in{changeset_data};
             Changeset log;
-            parse_changeset(in, log);
-            std::stringstream ss;
-            log.print(ss);
-            logger.trace("Changeset (parsed):\n%1", ss.str());
+            try {
+                parse_changeset(in, log);
+                std::stringstream ss;
+                log.print(ss);
+                logger.trace("Changeset (parsed):\n%1", ss.str());
+            }
+            catch (const BadChangesetError& err) {
+                logger.error("Unable to parse changeset: %1", err.what());
+            }
 #endif
         }
 

test/test_changeset_encoding.cpp

@@ -327,7 +327,7 @@ TEST(ChangesetParser_BadInstruction)
 {
     util::AppendBuffer<char> buffer;
     encode_instruction(buffer, 0x3e);
-    CHECK_BADCHANGESET(buffer, "unknown instruction");
+    CHECK_BADCHANGESET(buffer, "Unknown instruction type");
 }
 
 TEST(ChangesetParser_GoodInternString)

test/test_sync.cpp

@@ -789,10 +789,16 @@ struct ExpectChangesetError {
     }
 };
 
-void test_schema_mismatch(unit_test::TestContext& test_context, util::FunctionRef<void(WriteTransaction&)> fn_1,
-                          util::FunctionRef<void(WriteTransaction&)> fn_2, const char* expected_error_1,
+void test_schema_mismatch(unit_test::TestContext& test_context, util::FunctionRef<void(WriteTransaction&)>&& fn_1,
+                          util::FunctionRef<void(WriteTransaction&)>&& fn_2, const char* expected_error_1,
                           const char* expected_error_2 = nullptr)
 {
+    auto perform_write_transaction = [](DBRef db, util::FunctionRef<void(WriteTransaction&)>&& function) {
+        WriteTransaction wt(db);
+        function(wt);
+        return wt.commit();
+    };
+
     TEST_CLIENT_DB(db_1);
     TEST_CLIENT_DB(db_2);
 
@@ -813,8 +819,14 @@ void test_schema_mismatch(unit_test::TestContext& test_context, util::FunctionRe
     session_1.bind();
     session_2.bind();
 
-    write_transaction_notifying_session(db_1, session_1, fn_1);
-    write_transaction_notifying_session(db_2, session_2, fn_2);
+    // NOTE: There was a race condition with `write_transaction_notifying_session` where session_2
+    // was completing sync before the write transaction was completed, leading to a
+    // `realm::TableNameInUse` exception. Broke up this function and moved the call to
+    // `nonsync_transact_notify()` to after the write transactions.
+    auto version_1 = perform_write_transaction(db_1, std::move(fn_1));
+    auto version_2 = perform_write_transaction(db_2, std::move(fn_2));
+    session_1.nonsync_transact_notify(version_1);
+    session_2.nonsync_transact_notify(version_2);
 
     session_1.wait_for_upload_complete_or_client_stopped();
     session_2.wait_for_upload_complete_or_client_stopped();