Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

UBsan warning from ClientHistory::update_from_ref_and_version in client reset tests #7041

Closed
kiburtse opened this issue Oct 6, 2023 · 16 comments · Fixed by #7553
Closed
Assignees

Comments

@kiburtse
Copy link
Contributor

kiburtse commented Oct 6, 2023

during nightly build baas-integration-tests under ubuntu2004-ubsan reported an issue.

Core version

Core version: 13.22.0

Relevant lines from the log file:

[2023/10/06 00:04:46.966] 4: 13.076 s: DiscardLocal: open realm after client reset failure
[2023/10/06 00:04:47.810] 4: 14.406 s: flx: client reset
[2023/10/06 00:04:53.896] 4: ../src/realm/sync/noinst/client_history_impl.cpp:1202:45: runtime error: reference binding to null pointer of type 'realm::Group'
[2023/10/06 00:04:53.897] 4: SUMMARY: UndefinedBehaviorSanitizer: undefined-behavior ../src/realm/sync/noinst/client_history_impl.cpp:1202:45 in

so the test must be next after: 'flx: client reset' -c 'Recover: schema indexes match in before and after states'

The stack trace is missing from ubsan report sadly, but from what i can tell it can only happen from this code path

@danieltabacaru
Copy link
Collaborator

that seems to be more of a core issue than sync, but we'll have a look in the sync team too.

@kiburtse
Copy link
Contributor Author

During the same test on checkLinuxDebug_Sync jenkins runner with core 13.23.2 (happened on test run for #6911 - so just a few shifted lines from the code in a tag):

4: 
4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
4: realm-object-store-tests is a Catch2 v3.3.2 host application.
4: Run with -? for options
4: 
4: -------------------------------------------------------------------------------
4: flx: client reset
4:   Recover: schema indexes match in before and after states
4: -------------------------------------------------------------------------------
4: /mnt/jenkins/workspace/realm_realm-core_PR-6911/test/object-store/sync/flx_sync.cpp:1096
4: ...............................................................................
4: 
4: /mnt/jenkins/workspace/realm_realm-core_PR-6911/test/object-store/util/sync/sync_test_utils.cpp:517: FAILED:
4:   {Unknown expression after the reported line}
4: due to a fatal error condition:
4:   SIGABRT - Abort (abnormal termination) signal
4: 
4: 0.000 s: flx: client reset
4: realm-object-store-tests: src/catch2/reporters/catch_reporter_cumulative_base.cpp:133: virtual void Catch::CumulativeReporterBase::testCaseEnded(const Catch::TestCaseStats&): Assertion `m_sectionStack.size() == 0' failed.
4/4 Test #4: ObjectStoreTests-baas ............Subprocess aborted***Exception: 526.91 sec

Could this assertion failure - REQUIRE(file_ident.ident != 0) - be just a consequence of this ub, @danieltabacaru? Looks like a real recent issue.

@danieltabacaru
Copy link
Collaborator

Could this assertion failure - REQUIRE(file_ident.ident != 0) - be just a consequence of this ub, @danieltabacaru? Looks like a real recent issue.

I don't think they are linked. The assertion you point to would fail if the client never connected to the server.

@kiburtse
Copy link
Contributor Author

kiburtse commented Nov 2, 2023

So, now there is an assertion in place of this failure, which so only has been observed on linux builders, which sadly doesn't print the symbols for the stacktrace as was shown under #7101.

I've put some changes under #7109 to restore symbols partially, but it's not a solution. We should be using addr2line on ci artifacts to restore the stacktrace for failed builds really.

@kiburtse
Copy link
Contributor Author

So the linked pr did catch the failure with the stack trace once

Test log, assertion, stacktrace
[2023/11/09 10:38:51.195] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 2
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Commit of size 13056 done in 2031 us ref 2920
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query count: 'state != 2', limit = -1
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query matches: 0, Duration: 5 us
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query count: 'state == 2', limit = -1
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query matches: 0, Duration: 1 us
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query count: 'state == 2', limit = -1
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Query matches: 0, Duration: 1 us
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.198] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.200] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.200] 4: Realm sync client ([realm-core-13.23.2])
[2023/11/09 10:38:51.200] 4: Supported protocol versions: 2-10
[2023/11/09 10:38:51.200] 4: Platform: Linux Linux 5.4.0-1009-aws #9-Ubuntu SMP Sun Apr 12 19:46:01 UTC 2020 x86_64
[2023/11/09 10:38:51.200] 4: Build mode: Release
[2023/11/09 10:38:51.200] 4: Config param: one_connection_per_session = false
[2023/11/09 10:38:51.200] 4: Config param: connect_timeout = 120000 ms
[2023/11/09 10:38:51.200] 4: Config param: connection_linger_time = 30000 ms
[2023/11/09 10:38:51.200] 4: Config param: ping_keepalive_period = 60000 ms
[2023/11/09 10:38:51.200] 4: Config param: pong_keepalive_timeout = 120000 ms
[2023/11/09 10:38:51.200] 4: Config param: fast_reconnect_limit = 60000 ms
[2023/11/09 10:38:51.200] 4: Config param: disable_upload_compaction = false
[2023/11/09 10:38:51.200] 4: Config param: disable_sync_to_disk = false
[2023/11/09 10:38:51.200] 4: Config param: reconnect backoff info: max_delay: 300000 ms, initial_delay: 1000 ms, multiplier: 2
[2023/11/09 10:38:51.200] 4: App: register_email: realm_tests_do_autoverifyWumNRFCAlz@MpxfWkRYZu.com
[2023/11/09 10:38:51.200] 4: App: request location: http://localhost:9090/api/client/v2.0/app/flx_client_reset-llksb/location
[2023/11/09 10:38:51.202] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.205] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 3
[2023/11/09 10:38:51.205] 4: DB: 32426 Thread 140205901481920: Commit of size 2208 done in 2785 us ref 4160
[2023/11/09 10:38:51.205] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.205] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.206] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.206] 4: App: update_hostname: http://localhost:9090 | ws://localhost:9090
[2023/11/09 10:38:51.214] 4: App: log_in_with_credentials: app_id: flx_client_reset-llksb
[2023/11/09 10:38:51.214] 4: App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 13.23.2
[2023/11/09 10:38:51.231] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.231] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fc4"', limit = -1
[2023/11/09 10:38:51.231] 4: DB: 32426 Thread 140205901481920: Query found: 0, Duration: 6 us
[2023/11/09 10:38:51.231] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 4
[2023/11/09 10:38:51.233] 4: DB: 32426 Thread 140205901481920: Commit of size 2448 done in 1355 us ref 4296
[2023/11/09 10:38:51.234] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 5
[2023/11/09 10:38:51.234] 4: DB: 32426 Thread 140205901481920: Commit of size 2960 done in 1139 us ref 3464
[2023/11/09 10:38:51.235] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 6
[2023/11/09 10:38:51.235] 4: DB: 32426 Thread 140205901481920: Commit of size 1128 done in 1384 us ref 6520
[2023/11/09 10:38:51.236] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.236] 4: App: do_authenticated_request: GET http://localhost:9090/api/client/v2.0/auth/profile
[2023/11/09 10:38:51.239] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.240] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fc4"', limit = -1
[2023/11/09 10:38:51.240] 4: DB: 32426 Thread 140205901481920: Query found: 1, Duration: 8 us
[2023/11/09 10:38:51.240] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 7
[2023/11/09 10:38:51.241] 4: DB: 32426 Thread 140205901481920: Commit of size 1672 done in 1333 us ref 6656
[2023/11/09 10:38:51.243] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 8
[2023/11/09 10:38:51.243] 4: DB: 32426 Thread 140205901481920: Commit of size 1128 done in 1554 us ref 6792
[2023/11/09 10:38:51.243] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.243] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.244] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 9
[2023/11/09 10:38:51.244] 4: DB: 32426 Thread 140205901481920: Commit of size 328 done in 1192 us ref 6928
[2023/11/09 10:38:51.244] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.244] 4: App: register_email: realm_tests_do_autoverifyDVZAOpSsaR@wIqjygRPqk.com
[2023/11/09 10:38:51.252] 4: App: log_in_with_credentials: app_id: flx_client_reset-llksb
[2023/11/09 10:38:51.252] 4: App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 13.23.2
[2023/11/09 10:38:51.268] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.268] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fd0"', limit = -1
[2023/11/09 10:38:51.269] 4: DB: 32426 Thread 140205901481920: Query found: 0, Duration: 7 us
[2023/11/09 10:38:51.269] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 10
[2023/11/09 10:38:51.270] 4: DB: 32426 Thread 140205901481920: Commit of size 2560 done in 1309 us ref 7104
[2023/11/09 10:38:51.272] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 11
[2023/11/09 10:38:51.272] 4: DB: 32426 Thread 140205901481920: Commit of size 2864 done in 1625 us ref 10400
[2023/11/09 10:38:51.273] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 12
[2023/11/09 10:38:51.273] 4: DB: 32426 Thread 140205901481920: Commit of size 904 done in 1269 us ref 6920
[2023/11/09 10:38:51.273] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.273] 4: App: do_authenticated_request: GET http://localhost:9090/api/client/v2.0/auth/profile
[2023/11/09 10:38:51.277] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.277] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fd0"', limit = -1
[2023/11/09 10:38:51.277] 4: DB: 32426 Thread 140205901481920: Query found: 1, Duration: 7 us
[2023/11/09 10:38:51.277] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 13
[2023/11/09 10:38:51.278] 4: DB: 32426 Thread 140205901481920: Commit of size 1552 done in 1064 us ref 7096
[2023/11/09 10:38:51.279] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 14
[2023/11/09 10:38:51.279] 4: DB: 32426 Thread 140205901481920: Commit of size 976 done in 1163 us ref 10416
[2023/11/09 10:38:51.279] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.279] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.281] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 15
[2023/11/09 10:38:51.281] 4: DB: 32426 Thread 140205901481920: Commit of size 328 done in 1203 us ref 6920
[2023/11/09 10:38:51.281] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.281] 4: App: register_email: realm_tests_do_autoverifycKvUWjupeO@dlqmrjVCob.com
[2023/11/09 10:38:51.288] 4: App: log_in_with_credentials: app_id: flx_client_reset-llksb
[2023/11/09 10:38:51.288] 4: App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 13.23.2
[2023/11/09 10:38:51.305] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.305] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fdc"', limit = -1
[2023/11/09 10:38:51.306] 4: DB: 32426 Thread 140205901481920: Query found: 0, Duration: 6 us
[2023/11/09 10:38:51.306] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 16
[2023/11/09 10:38:51.307] 4: DB: 32426 Thread 140205901481920: Commit of size 2672 done in 1227 us ref 10424
[2023/11/09 10:38:51.309] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 17
[2023/11/09 10:38:51.309] 4: DB: 32426 Thread 140205901481920: Commit of size 2864 done in 1976 us ref 6912
[2023/11/09 10:38:51.310] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 18
[2023/11/09 10:38:51.310] 4: DB: 32426 Thread 140205901481920: Commit of size 928 done in 1371 us ref 7096
[2023/11/09 10:38:51.310] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.310] 4: App: do_authenticated_request: GET http://localhost:9090/api/client/v2.0/auth/profile
[2023/11/09 10:38:51.314] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.314] 4: DB: 32426 Thread 140205901481920: Query find all: 'identity == "654cb6bbf71c3bc563555fdc"', limit = -1
[2023/11/09 10:38:51.314] 4: DB: 32426 Thread 140205901481920: Query found: 1, Duration: 6 us
[2023/11/09 10:38:51.316] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 19
[2023/11/09 10:38:51.316] 4: DB: 32426 Thread 140205901481920: Commit of size 1592 done in 1381 us ref 12736
[2023/11/09 10:38:51.317] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 20
[2023/11/09 10:38:51.317] 4: DB: 32426 Thread 140205901481920: Commit of size 1040 done in 1252 us ref 12936
[2023/11/09 10:38:51.317] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.317] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_2S0erwzBmmexJefJ/mongodb-realm/flx_client_reset-llksb/server-utility/metadata/sync_metadata.realm
[2023/11/09 10:38:51.319] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 21
[2023/11/09 10:38:51.319] 4: DB: 32426 Thread 140205901481920: Commit of size 328 done in 1432 us ref 13120
[2023/11/09 10:38:51.319] 4: DB: 32426 Thread 140205901481920: DB closed
[2023/11/09 10:38:51.319] 4: DB: 32426 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_IlW6Ju/realm.iN3Q8w.local
[2023/11/09 10:38:51.321] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 2
[2023/11/09 10:38:51.321] 4: DB: 32426 Thread 140205901481920: Commit of size 5376 done in 1398 us ref 776
[2023/11/09 10:38:51.323] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 3
[2023/11/09 10:38:51.323] 4: DB: 32426 Thread 140205901481920: Commit of size 7440 done in 1003 us ref 2592
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 4
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Commit of size 2136 done in 1514 us ref 2832
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Query found: 0, Duration: 9 us
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Query find all: 'state == 6', limit = -1
[2023/11/09 10:38:51.324] 4: DB: 32426 Thread 140205901481920: Query found: 0, Duration: 2 us
[2023/11/09 10:38:51.328] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 5
[2023/11/09 10:38:51.328] 4: DB: 32426 Thread 140205901481920: Commit of size 7616 done in 3453 us ref 4176
[2023/11/09 10:38:51.329] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 6
[2023/11/09 10:38:51.329] 4: DB: 32426 Thread 140205901469440: Commit of size 9528 done in 1050 us ref 6464
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: Binding '/data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_IlW6Ju/realm.iN3Q8w.local' to ''
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: Activating
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: client_reset_config = false, Realm exists = true, client reset = false
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: client_file_ident = 0, client_file_ident_salt = 0
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: last_version_available  = 6
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: progress_download_server_version = 0
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: progress_download_client_version = 0
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: progress_upload_server_version = 0
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: progress_upload_client_version = 0
[2023/11/09 10:38:51.329] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 187, reliable_download_progress = false, snapshot version = 6
[2023/11/09 10:38:51.329] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 7
[2023/11/09 10:38:51.329] 4: Connection[1]: Connecting to 'ws://localhost:9090/api/client/v2.0/app/flx_client_reset-llksb/realm-sync'
[2023/11/09 10:38:51.330] 4: WebSocket::Websocket()
[2023/11/09 10:38:51.330] 4: Resolving 'localhost:9090'
[2023/11/09 10:38:51.330] 4: Connecting to endpoint '127.0.0.1:9090' (1/1)
[2023/11/09 10:38:51.330] 4: Connected to endpoint '127.0.0.1:9090' (from '127.0.0.1:34524')
[2023/11/09 10:38:51.332] 4: WebSocket::initiate_client_handshake()
[2023/11/09 10:38:51.332] 4: DB: 32426 Thread 140205901481920: Commit of size 3680 done in 2824 us ref 8288
[2023/11/09 10:38:51.334] 4: DB: 32426 Thread 140205901481920: Initiate commit version: 8
[2023/11/09 10:38:51.334] 4: DB: 32426 Thread 140205901481920: Commit of size 2984 done in 1287 us ref 7784
[2023/11/09 10:38:51.334] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 547, reliable_download_progress = false, snapshot version = 8
[2023/11/09 10:38:51.335] 4: WebSocket::handle_http_response_received()
[2023/11/09 10:38:51.335] 4: Connection[1]: Negotiated protocol version: 9
[2023/11/09 10:38:51.335] 4: Connection[1]: Connected to app services with request id: "654cb6bbf71c3bc563555fe2"
[2023/11/09 10:38:51.335] 4: Connection[1]: Will emit a ping in 46694 milliseconds
[2023/11/09 10:38:51.335] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/09 10:38:51.358] 4: Connection[1]: Session[1]: Received: ERROR "Client tried to connect using flexible sync before initial sync is complete" (error_code=229, is_fatal=false, error_action=Transient)
[2023/11/09 10:38:51.358] 4: Connection[1]: Session[1]: Suspended
[2023/11/09 10:38:51.358] 4: Connection[1]: Session[1]: Will attempt to resume session after 1556 milliseconds
[2023/11/09 10:38:51.358] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/09 10:38:52.916] 4: Connection[1]: Session[1]: Resumed
[2023/11/09 10:38:52.916] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/09 10:38:52.918] 4: Connection[1]: Session[1]: Received: ERROR "Client tried to connect using flexible sync before initial sync is complete" (error_code=229, is_fatal=false, error_action=Transient)
[2023/11/09 10:38:52.918] 4: Connection[1]: Session[1]: Suspended
[2023/11/09 10:38:52.918] 4: Connection[1]: Session[1]: Will attempt to resume session after 3582 milliseconds
[2023/11/09 10:38:56.504] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/09 10:38:56.504] 4: Connection[1]: Session[1]: Resumed
[2023/11/09 10:38:56.504] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/09 10:38:56.509] 4: Connection[1]: Session[1]: Received: IDENT(client_file_ident=18, client_file_ident_salt=1112097515506183554)
[2023/11/09 10:38:56.510] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 9
[2023/11/09 10:38:56.510] 4: DB: 32426 Thread 140205901469440: Commit of size 1168 done in 1108 us ref 7936
[2023/11/09 10:38:56.510] 4: DB: 32426 Thread 140205901469440: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/09 10:38:56.510] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 14 us
[2023/11/09 10:38:56.510] 4: Connection[1]: Session[1]: Sending: IDENT(client_file_ident=18, client_file_ident_salt=1112097515506183554, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0, query_version=0, query_size=2, query="{}")
[2023/11/09 10:38:56.514] 4: Connection[1]: Session[1]: Sending: MARK(request_ident=1)
[2023/11/09 10:38:56.514] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=212, uncompressed_body_size=212
[2023/11/09 10:38:56.514] 4: Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=17, client_version=0, origin_timestamp=279455936515, origin_file_ident=1, original_changeset_size=184, changeset_size=184)
[2023/11/09 10:38:56.514] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=17, download_client_version=0, latest_server_version=17, latest_server_version_salt=0, upload_client_version=0, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=1, ...)
[2023/11/09 10:38:56.514] 4: DB: 32426 Thread 140205901469440: Query find all: 'query_version != 0', limit = -1
[2023/11/09 10:38:56.514] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 2 us
[2023/11/09 10:38:56.516] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 10
[2023/11/09 10:38:56.516] 4: DB: 32426 Thread 140205901469440: Commit of size 3928 done in 1494 us ref 8520
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Created new pending bootstrap object for query version 0
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Finalized pending bootstrap object for query version 0
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 0. (changesets: 1, original total changeset size: 184)
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 8 instructions, local: 2 changeset(s) / 16 instructions, conflict group(s): 3)
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Finished transforming 2 local changesets through 1 incoming changesets (16 vs 8 instructions, in 3 conflict groups)
[2023/11/09 10:38:56.516] 4: Connection[1]: Session[1]: Removing pending bootstrap obj for query version 0
[2023/11/09 10:38:56.518] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 11
[2023/11/09 10:38:56.518] 4: DB: 32426 Thread 140205901469440: Commit of size 3616 done in 1075 us ref 9296
[2023/11/09 10:38:56.518] 4: Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2023/11/09 10:38:56.518] 4: Connection[1]: Session[1]: Integrated 1 changesets from pending bootstrap for query version 0, producing client version 11 in 1 ms. 0 changesets remaining in bootstrap
[2023/11/09 10:38:56.518] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 184, downloadable(total) = 184, uploaded = 0, uploadable = 547, reliable_download_progress = true, snapshot version = 11
[2023/11/09 10:38:56.518] 4: DB: 32426 Thread 140205901469440: Query find all: 'version < 0', limit = -1
[2023/11/09 10:38:56.518] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 3 us
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 12
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Commit of size 1640 done in 1219 us ref 9840
[2023/11/09 10:38:56.519] 4: Connection[1]: Session[1]: Received: MARK(request_ident=1)
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Query found: 1, Duration: 11 us
[2023/11/09 10:38:56.519] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=6, progress_server_version=0, locked_server_version=17, num_changesets=1)
[2023/11/09 10:38:56.519] 4: Connection[1]: Session[1]: Fetching changeset for upload (client_version=5, server_version=0, changeset_size=187, origin_timestamp=279455931324, origin_file_ident=0)
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.519] 4: DB: 32426 Thread 140205901469440: Query found: 1, Duration: 7 us
[2023/11/09 10:38:56.519] 4: Connection[1]: Session[1]: Sending: QUERY(query_version=1, query_size=53, query="{"TopLevel":"(_id == oid(654cb6bb94de313c1975be50))"}", snapshot_version=6)
[2023/11/09 10:38:56.520] 4: Connection[1]: Session[1]: Sending: MARK(request_ident=2)
[2023/11/09 10:38:56.520] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.520] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 5 us
[2023/11/09 10:38:56.520] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=12, progress_server_version=17, locked_server_version=17, num_changesets=1)
[2023/11/09 10:38:56.520] 4: Connection[1]: Session[1]: Fetching changeset for upload (client_version=8, server_version=0, changeset_size=360, origin_timestamp=279455931333, origin_file_ident=0)
[2023/11/09 10:38:56.520] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.520] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 5 us
[2023/11/09 10:38:56.527] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=0, uncompressed_body_size=0
[2023/11/09 10:38:56.527] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=18, download_client_version=5, latest_server_version=18, latest_server_version_salt=2772410325641581317, upload_client_version=6, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=0, ...)
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 13
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Commit of size 1200 done in 1323 us ref 10104
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 6 us
[2023/11/09 10:38:56.528] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=13, progress_server_version=18, locked_server_version=18, num_changesets=0)
[2023/11/09 10:38:56.528] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 184, downloadable(total) = 184, uploaded = 187, uploadable = 547, reliable_download_progress = true, snapshot version = 13
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.528] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 5 us
[2023/11/09 10:38:56.537] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=24, uncompressed_body_size=24
[2023/11/09 10:38:56.537] 4: Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=19, client_version=5, origin_timestamp=279455936537, origin_file_ident=1, original_changeset_size=0, changeset_size=0)
[2023/11/09 10:38:56.537] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=19, download_client_version=5, latest_server_version=19, latest_server_version_salt=0, upload_client_version=6, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=1, num_changesets=1, ...)
[2023/11/09 10:38:56.537] 4: DB: 32426 Thread 140205901469440: Query find all: 'query_version != 1', limit = -1
[2023/11/09 10:38:56.537] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 1 us
[2023/11/09 10:38:56.538] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 14
[2023/11/09 10:38:56.538] 4: DB: 32426 Thread 140205901469440: Commit of size 3976 done in 1397 us ref 10384
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Created new pending bootstrap object for query version 1
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Finalized pending bootstrap object for query version 1
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 1. (changesets: 1, original total changeset size: 0)
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 0 instructions, local: 1 changeset(s) / 8 instructions, conflict group(s): 1)
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Finished transforming 1 local changesets through 1 incoming changesets (8 vs 0 instructions, in 1 conflict groups)
[2023/11/09 10:38:56.538] 4: Connection[1]: Session[1]: Removing pending bootstrap obj for query version 1
[2023/11/09 10:38:56.540] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 15
[2023/11/09 10:38:56.540] 4: DB: 32426 Thread 140205901469440: Commit of size 3912 done in 1323 us ref 10680
[2023/11/09 10:38:56.540] 4: Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2023/11/09 10:38:56.540] 4: Connection[1]: Session[1]: Integrated 1 changesets from pending bootstrap for query version 1, producing client version 15 in 1 ms. 0 changesets remaining in bootstrap
[2023/11/09 10:38:56.540] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.540] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 7 us
[2023/11/09 10:38:56.540] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=15, progress_server_version=19, locked_server_version=19, num_changesets=0)
[2023/11/09 10:38:56.540] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 184, downloadable(total) = 184, uploaded = 187, uploadable = 547, reliable_download_progress = true, snapshot version = 15
[2023/11/09 10:38:56.541] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 16
[2023/11/09 10:38:56.541] 4: DB: 32426 Thread 140205901469440: Commit of size 1680 done in 1142 us ref 11000
[2023/11/09 10:38:56.541] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.541] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 6 us
[2023/11/09 10:38:56.541] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=16, progress_server_version=19, locked_server_version=19, num_changesets=0)
[2023/11/09 10:38:56.541] 4: Connection[1]: Session[1]: Received: MARK(request_ident=2)
[2023/11/09 10:38:56.541] 4: Connection[1]: Session[1]: Marking query version 1 as complete after receiving MARK message
[2023/11/09 10:38:56.542] 4: DB: 32426 Thread 140205901469440: Query find all: 'version < 1', limit = -1
[2023/11/09 10:38:56.542] 4: DB: 32426 Thread 140205901469440: Query found: 1, Duration: 3 us
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 17
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Commit of size 2384 done in 1180 us ref 11344
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 6 us
[2023/11/09 10:38:56.543] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=17, progress_server_version=19, locked_server_version=19, num_changesets=0)
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.543] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 4 us
[2023/11/09 10:38:56.550] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=0, uncompressed_body_size=0
[2023/11/09 10:38:56.550] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=20, download_client_version=8, latest_server_version=20, latest_server_version_salt=594246577799486668, upload_client_version=13, upload_server_version=18, downloadable_bytes=0, last_in_batch=true, query_version=1, num_changesets=0, ...)
[2023/11/09 10:38:56.550] 4: DB: 32426 Thread 140205901469440: Initiate commit version: 18
[2023/11/09 10:38:56.550] 4: DB: 33878 Thread 140205901481920: Open file: /data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_IlW6Ju/realm.iN3Q8w.local
[2023/11/09 10:38:56.550] 4: DB: 33878 Thread 140205901481920: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/09 10:38:56.550] 4: DB: 33878 Thread 140205901481920: Query found: 1, Duration: 8 us
[2023/11/09 10:38:56.550] 4: DB: 33878 Thread 140205901481920: Query find all: 'state == 6', limit = -1
[2023/11/09 10:38:56.550] 4: DB: 33878 Thread 140205901481920: Query found: 0, Duration: 2 us
[2023/11/09 10:38:56.551] 4: DB: 32426 Thread 140205901469440: Commit of size 1248 done in 1352 us ref 11704
[2023/11/09 10:38:56.551] 4: DB: 32426 Thread 140205901469440: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/09 10:38:56.551] 4: DB: 32426 Thread 140205901469440: Query found: 0, Duration: 7 us
[2023/11/09 10:38:56.551] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=18, progress_server_version=20, locked_server_version=20, num_changesets=0)
[2023/11/09 10:38:56.551] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 184, downloadable(total) = 184, uploaded = 547, uploadable = 547, reliable_download_progress = true, snapshot version = 18
[2023/11/09 10:38:56.551] 4: Connection[1]: Session[1]: Initiating deactivation
[2023/11/09 10:38:56.551] 4: DB: 32426 Thread 140205901469440: DB closed
[2023/11/09 10:38:56.551] 4: Connection[1]: Session[2]: Binding '/data/mci/80cb2a84bb84389e138663a17be4dd8c/tmp/realm_IlW6Ju/realm.iN3Q8w.local' to ''
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: Activating
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: client_reset_config = false, Realm exists = true, client reset = false
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: client_file_ident = 18, client_file_ident_salt = 1112097515506183554
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: last_version_available  = 18
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: progress_download_server_version = 20
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: progress_download_client_version = 8
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: progress_upload_server_version = 18
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: progress_upload_client_version = 13
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: Progress handler called, downloaded = 184, downloadable(total) = 184, uploaded = 547, uploadable = 547, reliable_download_progress = false, snapshot version = 18
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: Sending: BIND(session_ident=2, need_client_file_ident=false, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/09 10:38:56.552] 4: DB: 33878 Thread 140205901469440: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/09 10:38:56.552] 4: DB: 33878 Thread 140205901469440: Query found: 1, Duration: 7 us
[2023/11/09 10:38:56.552] 4: Connection[1]: Session[2]: Sending: IDENT(client_file_ident=18, client_file_ident_salt=1112097515506183554, scan_server_version=20, scan_client_version=8, latest_server_version=20, latest_server_version_salt=594246577799486668, query_version=1, query_size=53, query="{"TopLevel":"(_id == oid(654cb6bb94de313c1975be50))"}")
[2023/11/09 10:38:56.558] 4: Connection[1]: Session[2]: Sending: MARK(request_ident=1)
[2023/11/09 10:38:56.558] 4: ../src/realm/sync/noinst/client_history_impl.cpp:1196: [realm-core-13.23.2] Assertion failed: m_group with (ref, version) =  [10120, 18]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests() [0x33fe486]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm4util19terminate_with_infoEPKcS2_lS2_OSt16initializer_listINS0_9PrintableEE+0x16e) [0x33fe42e]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm4util19terminate_with_infoIJRmS2_EEEvPKciS4_S4_DpOT_+0x66) [0x2e9cbe6]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm4sync13ClientHistory27update_from_ref_and_versionEmm+0x86b) [0x2e9946b]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm11Transaction21internal_advance_readINS_5_impl23NullInstructionObserverEEEbPT_NS_9VersionIDERNS2_7HistoryEb+0x67d) [0x2ae219d]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm11Transaction16promote_to_writeINS_5_impl23NullInstructionObserverEEEbPT_b+0x67a) [0x2b79d5a]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm5Realm13update_schemaENS_6SchemaEmSt8functionIFvSt10shared_ptrIS0_ES4_RS1_EES2_IFvS4_EEb+0x2b8) [0x2b70628]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm5_impl16RealmCoordinator12do_get_realmEONS_11RealmConfigERSt10shared_ptrINS_5RealmEESt8optionalINS_9VersionIDEERNS_4util17CheckedUniqueLockEb+0x7a9) [0x2bd5859]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm5_impl16RealmCoordinator9get_realmENS_11RealmConfigESt8optionalINS_9VersionIDEE+0x276) [0x2bd4f76]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5realm5Realm16get_shared_realmENS_11RealmConfigE+0xdd) [0x2b6e3bd]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests() [0x28f71dd]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5Catch10RunContext20invokeActiveTestCaseEv+0xe8) [0x2a98c68]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5Catch10RunContext14runCurrentTestERNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEES7_+0x4be) [0x2a947ce]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5Catch10RunContext7runTestERKNS_14TestCaseHandleE+0x700) [0x2a93830]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5Catch7Session11runInternalEv+0x9e5) [0x2a28175]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_ZN5Catch7Session3runEv+0x140) [0x2a27540]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(main+0x8e4) [0x19a6f14]
[2023/11/09 10:38:56.558] 4: /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf3) [0x7f843bf89083]
[2023/11/09 10:38:56.558] 4: /data/mci/80cb2a84bb84389e138663a17be4dd8c/realm-core/build/test/object-store/RelWithDebInfo/realm-object-store-tests(_start+0x2e) [0x156f02e]
[2023/11/09 10:38:56.558] 4: !!! IMPORTANT: Please report this at https://github.com/realm/realm-core/issues/new/choose
[2023/11/09 10:38:56.558] 4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2023/11/09 10:38:56.558] 4: realm-object-store-tests is a Catch2 v3.3.2 host application.
[2023/11/09 10:38:56.558] 4: Run with -? for options
[2023/11/09 10:38:56.558] 4:
[2023/11/09 10:38:56.558] 4: -------------------------------------------------------------------------------
[2023/11/09 10:38:56.558] 4: flx: client reset
[2023/11/09 10:38:56.558] 4:   Recover: schema indexes match in before and after states
[2023/11/09 10:38:56.558] 4: -------------------------------------------------------------------------------
[2023/11/09 10:38:56.558] 4: ../test/object-store/sync/flx_sync.cpp:1096
[2023/11/09 10:38:56.558] 4: ...............................................................................
[2023/11/09 10:38:56.558] 4:
[2023/11/09 10:38:56.558] 4: ../test/object-store/sync/flx_sync.cpp:1096: FAILED:
[2023/11/09 10:38:56.558] 4:   {Unknown expression after the reported line}
[2023/11/09 10:38:56.558] 4: due to a fatal error condition:
[2023/11/09 10:38:56.558] 4:   SIGABRT - Abort (abnormal termination) signal
[2023/11/09 10:38:56.558] 4:
[2023/11/09 10:38:56.558] 4: Assertion failure: ../test/object-store/sync/flx_sync.cpp:1096
[2023/11/09 10:38:56.558] 4: 	 from expresion: '{Unknown expression after the reported line}'
[2023/11/09 10:38:56.558] 4: 	 with expansion: '{Unknown expression after the reported line}'
[2023/11/09 10:38:56.558] 4: 	 message: SIGABRT - Abort (abnormal termination) signal
[2023/11/09 10:38:56.559] 4:
[2023/11/09 10:38:56.559] 4: 0.000 s: flx: client reset

but it doesn't provide much new info from what i can tell.

Essentially the failure happens during second open of main realm after client reset.

Is there anything obviously suspicious in test log above?

@danieltabacaru
Copy link
Collaborator

I looked a bit at the logs and found something odd. The commit producing client version 18 has ref 11704, but the assertion logs 10120. Is that expected?

@kiburtse
Copy link
Contributor Author

I looked a bit at the logs and found something odd. The commit producing client version 18 has ref 11704, but the assertion logs 10120. Is that expected?

well it's a different ref - history ref, and not a new top level commit ref. So, i'd say yes, it's expected in logs.

@kiburtse
Copy link
Contributor Author

I think i know how this has happened - it can also be seen in the original CI failure log:

[2023/10/06 00:04:53.895] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=20, download_client_version=8, latest_server_version=20, latest_server_version_salt=172203137570149841, upload_client_version=13, upload_server_version=18, downloadable_bytes=0, last_in_batch=true, query_version=1, num_changesets=0, ...)
[2023/10/06 00:04:53.895] 4: DB: 469 Thread 140615787591424: Initiate commit version: 18
[2023/10/06 00:04:53.895] 4: DB: 346 Thread 140615787603968: Open file: /data/mci/77f75a0e9e2496472107f846e0dfde3f/tmp/realm_KYkk9r/realm.I8McJr.local
[2023/10/06 00:04:53.895] 4: DB: 346 Thread 140615787603968: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/10/06 00:04:53.895] 4: DB: 346 Thread 140615787603968: Query found: 1, Duration: 7 us
[2023/10/06 00:04:53.895] 4: DB: 346 Thread 140615787603968: Query find all: 'state == 6', limit = -1
[2023/10/06 00:04:53.895] 4: DB: 346 Thread 140615787603968: Query found: 0, Duration: 2 us
[2023/10/06 00:04:53.896] 4: DB: 469 Thread 140615787591424: Commit of size 1248 done in 1541 us ref 11712
[2023/10/06 00:04:53.896] 4: DB: 469 Thread 140615787591424: Query find all: 'version > 1 and (state == 1 or state == 2) and snapshot_version > 14', limit = -1
[2023/10/06 00:04:53.896] 4: ../src/realm/sync/noinst/client_history_impl.cpp:1202:45: runtime error: reference binding to null pointer of type 'realm::Group'

sync session received the download message on its thread 140615787591424 and started to integrate it, meanwhile the test itself on main thread 140615787603968 starts opening the realm and updating schema.

Simplified stacktrace of the assertion:

sync::ClientHistory::update_from_ref_and_version                                                                                                                                                                                                                                                                                     
Transaction::internal_advance_read                                                                                                                                                                                                                                                                                                   
Transaction::promote_to_write                                                                                                                                                                                                                                                                                                        
Realm::update_schema                                                                                                                                                                                                                                                                                                                 
_impl::RealmCoordinator::do_get_realm                                                                                                                                                                                                                                                                                                
_impl::RealmCoordinator::get_realm                                                                                                                                                                                                                                                                                                   
Realm::get_shared_realm

So the Transaction::internal_advance_read doesn't hit shortcut path due to updated history and tries to call ClientHistory::update_from_ref_and_version which hits the assertion.

The problem is that during promote_to_write the group is set through Replication::initiate_transact, which is called only after Transaction::internal_advance_read.

@kiburtse kiburtse self-assigned this Nov 24, 2023
@kiburtse
Copy link
Contributor Author

One more occurence with realm-core-14.3.0 on the same test: ci run

test log
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Realm sync client ([realm-core-14.3.0])
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Supported protocol versions: 2-12
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Platform: Linux Linux 5.15.0-1020-aws #24-Ubuntu SMP Thu Sep 1 16:05:45 UTC 2022 aarch64
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Build mode: Debug
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: one_connection_per_session = false
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: connect_timeout = 120000 ms
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: connection_linger_time = 30000 ms
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: ping_keepalive_period = 60000 ms
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: pong_keepalive_timeout = 120000 ms
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: fast_reconnect_limit = 60000 ms
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: disable_upload_compaction = false
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: disable_sync_to_disk = false
[2024/03/19 22:18:16.674] 4: Realm.Sync.Client.Session - Config param: reconnect backoff info: max_delay: 300000 ms, initial_delay: 1000 ms, multiplier: 2, jitter: 1/4
[2024/03/19 22:18:16.674] 4: Realm.App - App: register_email: realm_tests_do_autoverifyMXowYbqfFR@sOFTAdBwjR.com
[2024/03/19 22:18:16.674] 4: Realm.App - App: request location: http://3.237.39.133:35948/api/client/v2.0/app/flx_client_reset-volyj/location
[2024/03/19 22:18:16.676] 4: Realm.App - App: Location info returned for deployment model: GLOBAL(US-VA)
[2024/03/19 22:18:16.676] 4: Realm.App - App: update_hostname: http://3.237.39.133:35948 | ws://3.237.39.133:35948 | base URL: http://3.237.39.133:35948
[2024/03/19 22:18:16.681] 4: Realm.App - App: log_in_with_credentials: app_id: flx_client_reset-volyj
[2024/03/19 22:18:16.682] 4: Realm.App - App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 14.3.0
[2024/03/19 22:18:16.715] 4: Realm.App - App: do_authenticated_request: GET http://3.237.39.133:35948/api/client/v2.0/auth/profile
[2024/03/19 22:18:16.731] 4: Realm.App - App: register_email: realm_tests_do_autoverifygXlqzItiVa@qiQtgIVhfo.com
[2024/03/19 22:18:16.737] 4: Realm.App - App: log_in_with_credentials: app_id: flx_client_reset-volyj
[2024/03/19 22:18:16.737] 4: Realm.App - App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 14.3.0
[2024/03/19 22:18:16.772] 4: Realm.App - App: do_authenticated_request: GET http://3.237.39.133:35948/api/client/v2.0/auth/profile
[2024/03/19 22:18:16.788] 4: Realm.App - App: register_email: realm_tests_do_autoverifySthhfAFXFE@UDjzZjCfxw.com
[2024/03/19 22:18:16.794] 4: Realm.App - App: log_in_with_credentials: app_id: flx_client_reset-volyj
[2024/03/19 22:18:16.794] 4: Realm.App - App: version info: platform: Linux  version: Object Store Platform Version Blah - sdk: An sdk name - sdk version: An sdk version - core version: 14.3.0
[2024/03/19 22:18:16.829] 4: Realm.App - App: do_authenticated_request: GET http://3.237.39.133:35948/api/client/v2.0/auth/profile
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Binding '/data/mci/dc1805e3be04a52a82d59cd34dec2adf/tmp/realm_Uvh5fk/realm.VvFo0Z.local' to ''
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Activating
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: client_reset_config = false, Realm exists = true
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: client_file_ident = 0, client_file_ident_salt = 0
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: last_version_available  = 6
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: progress_download_server_version = 0
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: progress_download_client_version = 0
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: progress_upload_server_version = 0
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: progress_upload_client_version = 0
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Session - Connection[1]: Connecting to 'ws://3.237.39.133:35948/api/client/v2.0/app/flx_client_reset-volyj/realm-sync'
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Network - WebSocket::Websocket()
[2024/03/19 22:18:16.864] 4: Realm.Sync.Client.Network - Resolving '3.237.39.133:35948'
[2024/03/19 22:18:16.865] 4: Realm.Sync.Client.Network - Connecting to endpoint '3.237.39.133:35948' (1/1)
[2024/03/19 22:18:16.865] 4: Realm.Sync.Client.Network - Connected to endpoint '3.237.39.133:35948' (from '10.122.53.85:57248')
[2024/03/19 22:18:16.870] 4: Realm.Sync.Client.Network - WebSocket::initiate_client_handshake()
[2024/03/19 22:18:16.870] 4: Realm.Sync.Client.Network - WebSocket::handle_http_response_received()
[2024/03/19 22:18:16.870] 4: Realm.Sync.Client.Session - Connection[1]: Negotiated protocol version: 12
[2024/03/19 22:18:16.870] 4: Realm.Sync.Client.Session - Connection[1]: Connected to app services with request id: "65fa0f2895be66c8c458a0d1"
[2024/03/19 22:18:16.870] 4: Realm.Sync.Client.Session - Connection[1]: Will emit a ping in 55434 milliseconds
[2024/03/19 22:18:16.871] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"schemaVersion":0,"sessionReason":0}")
[2024/03/19 22:18:16.875] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: IDENT(client_file_ident=34, client_file_ident_salt=3393454874192951955)
[2024/03/19 22:18:16.878] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: IDENT(client_file_ident=34, client_file_ident_salt=3393454874192951955, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0, query_version=0, query_size=2, query="{}")
[2024/03/19 22:18:16.878] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: MARK(request_ident=1)
[2024/03/19 22:18:16.971] 4: Realm.Sync.Client.Changeset - Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=23, uncompressed_body_size=23
[2024/03/19 22:18:16.971] 4: Realm.Sync.Client.Changeset - Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=1, client_version=0, origin_timestamp=290816296883, origin_file_ident=1, original_changeset_size=0, changeset_size=0)
[2024/03/19 22:18:16.971] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=1, download_client_version=0, latest_server_version=1, latest_server_version_salt=0, upload_client_version=0, upload_server_version=0, progress_estimate=0, last_in_batch=true, query_version=0, num_changesets=1, ...)
[2024/03/19 22:18:16.974] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Created new pending bootstrap object for query version 0
[2024/03/19 22:18:16.974] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finalized pending bootstrap object for query version 0
[2024/03/19 22:18:16.974] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 0. (changesets: 1, original total changeset size: 0)
[2024/03/19 22:18:16.975] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 0 instructions, local: 2 changeset(s) / 16 instructions, conflict group(s): 3)
[2024/03/19 22:18:16.975] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finished transforming 2 local changesets through 1 incoming changesets (16 vs 0 instructions, in 3 conflict groups)
[2024/03/19 22:18:16.976] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Removing pending bootstrap obj for query version 0
[2024/03/19 22:18:16.978] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2024/03/19 22:18:16.978] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Integrated 1 changesets from pending bootstrap for query version 0, producing client version 11 in 3 ms. 0 changesets remaining in bootstrap
[2024/03/19 22:18:16.979] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable = 0, estimate = 0.0000, uploaded = 0, uploadable = 548, estimate = 0.0000, snapshot version = 11
[2024/03/19 22:18:16.982] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: MARK(request_ident=1)
[2024/03/19 22:18:16.982] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=6, progress_server_version=0, locked_server_version=1, num_changesets=1)
[2024/03/19 22:18:16.982] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Fetching changeset for upload (client_version=5, server_version=0, changeset_size=187, origin_timestamp=290816296856, origin_file_ident=0)
[2024/03/19 22:18:16.983] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: QUERY(query_version=1, query_size=53, query="{"TopLevel":"(_id == oid(65fa0f285cedece440ea2ccc))"}", snapshot_version=6)
[2024/03/19 22:18:16.983] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: MARK(request_ident=2)
[2024/03/19 22:18:16.983] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=12, progress_server_version=1, locked_server_version=1, num_changesets=1)
[2024/03/19 22:18:16.983] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Fetching changeset for upload (client_version=8, server_version=0, changeset_size=361, origin_timestamp=290816296870, origin_file_ident=0)
[2024/03/19 22:18:17.113] 4: Realm.Sync.Client.Changeset - Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=0, uncompressed_body_size=0
[2024/03/19 22:18:17.113] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=2, download_client_version=5, latest_server_version=3, latest_server_version_salt=0, upload_client_version=6, upload_server_version=0, progress_estimate=1, last_in_batch=true, query_version=0, num_changesets=0, ...)
[2024/03/19 22:18:17.116] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable = 0, estimate = 1.0000, uploaded = 187, uploadable = 548, estimate = 0.3412, snapshot version = 13
[2024/03/19 22:18:17.116] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=13, progress_server_version=2, locked_server_version=2, num_changesets=0)
[2024/03/19 22:18:17.213] 4: Realm.Sync.Client.Changeset - Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=23, uncompressed_body_size=23
[2024/03/19 22:18:17.213] 4: Realm.Sync.Client.Changeset - Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=3, client_version=5, origin_timestamp=290816297019, origin_file_ident=1, original_changeset_size=0, changeset_size=0)
[2024/03/19 22:18:17.213] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=3, download_client_version=5, latest_server_version=4, latest_server_version_salt=348029092965969140, upload_client_version=13, upload_server_version=2, progress_estimate=1, last_in_batch=true, query_version=1, num_changesets=1, ...)
[2024/03/19 22:18:17.216] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Created new pending bootstrap object for query version 1
[2024/03/19 22:18:17.216] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finalized pending bootstrap object for query version 1
[2024/03/19 22:18:17.216] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 1. (changesets: 1, original total changeset size: 0)
[2024/03/19 22:18:17.217] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 0 instructions, local: 1 changeset(s) / 8 instructions, conflict group(s): 1)
[2024/03/19 22:18:17.217] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Finished transforming 1 local changesets through 1 incoming changesets (8 vs 0 instructions, in 1 conflict groups)
[2024/03/19 22:18:17.217] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Removing pending bootstrap obj for query version 1
[2024/03/19 22:18:17.220] 4: Realm.Sync.Client.Changeset - Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2024/03/19 22:18:17.220] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Integrated 1 changesets from pending bootstrap for query version 1, producing client version 15 in 3 ms. 0 changesets remaining in bootstrap
[2024/03/19 22:18:17.220] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable = 0, estimate = 1.0000, uploaded = 548, uploadable = 548, estimate = 1.0000, snapshot version = 15
[2024/03/19 22:18:17.220] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable = 0, estimate = 1.0000, uploaded = 548, uploadable = 548, estimate = 1.0000, snapshot version = 15
[2024/03/19 22:18:17.221] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=15, progress_server_version=3, locked_server_version=3, num_changesets=0)
[2024/03/19 22:18:17.224] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=16, progress_server_version=3, locked_server_version=3, num_changesets=0)
[2024/03/19 22:18:17.224] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: MARK(request_ident=2)
[2024/03/19 22:18:17.224] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Marking query version 1 as complete after receiving MARK message
[2024/03/19 22:18:17.228] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=17, progress_server_version=3, locked_server_version=3, num_changesets=0)
[2024/03/19 22:18:17.313] 4: Realm.Sync.Client.Changeset - Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=0, uncompressed_body_size=0
[2024/03/19 22:18:17.313] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=4, download_client_version=8, latest_server_version=4, latest_server_version_salt=348029092965969140, upload_client_version=17, upload_server_version=3, progress_estimate=1, last_in_batch=true, query_version=1, num_changesets=0, ...)
[2024/03/19 22:18:17.316] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable = 0, estimate = 1.0000, uploaded = 548, uploadable = 548, estimate = 1.0000, snapshot version = 18
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/src/realm/sync/noinst/client_history_impl.cpp:1242: [realm-core-14.3.0] Assertion failed: m_group
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x688cf24) [0xaaaae929cf24]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x68f2a5c) [0xaaaae9302a5c]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x68f2e1c) [0xaaaae9302e1c]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x68f2c94) [0xaaaae9302c94]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5eb03d0) [0xaaaae88c03d0]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5798270) [0xaaaae81a8270]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5915350) [0xaaaae8325350]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5913178) [0xaaaae8323178]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x58faa90) [0xaaaae830aa90]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5a13a40) [0xaaaae8423a40]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5a11f24) [0xaaaae8421f24]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x58f57ec) [0xaaaae83057ec]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5044dec) [0xaaaae7a54dec]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x55ba00c) [0xaaaae7fca00c]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x55849dc) [0xaaaae7f949dc]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5581bd8) [0xaaaae7f91bd8]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x5581450) [0xaaaae7f91450]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x557d39c) [0xaaaae7f8d39c]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x54c2268) [0xaaaae7ed2268]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x54c4edc) [0xaaaae7ed4edc]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x54c43d8) [0xaaaae7ed43d8]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x3774ba8) [0xaaaae6184ba8]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x3766a2c) [0xaaaae6176a2c]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x548fe18) [0xaaaae7e9fe18]
[2024/03/19 22:18:17.316] 4: /lib/aarch64-linux-gnu/libc.so.6(+0x273fc) [0xffffa59673fc]
[2024/03/19 22:18:17.316] 4: /lib/aarch64-linux-gnu/libc.so.6(__libc_start_main+0x98) [0xffffa59674cc]
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/build/test/object-store/Debug/realm-object-store-tests(+0x65daf0) [0xaaaae306daf0]
[2024/03/19 22:18:17.316] 4: !!! IMPORTANT: Please report this at https://github.com/realm/realm-core/issues/new/choose
[2024/03/19 22:18:17.316] 4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2024/03/19 22:18:17.316] 4: realm-object-store-tests is a Catch2 v3.5.2 host application.
[2024/03/19 22:18:17.316] 4: Run with -? for options
[2024/03/19 22:18:17.316] 4:
[2024/03/19 22:18:17.316] 4: -------------------------------------------------------------------------------
[2024/03/19 22:18:17.316] 4: flx: client reset
[2024/03/19 22:18:17.316] 4:   Recover: schema indexes match in before and after states
[2024/03/19 22:18:17.316] 4: -------------------------------------------------------------------------------
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/test/object-store/sync/flx_sync.cpp:1242
[2024/03/19 22:18:17.316] 4: ...............................................................................
[2024/03/19 22:18:17.316] 4:
[2024/03/19 22:18:17.316] 4: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/test/object-store/sync/flx_sync.cpp:1242: FAILED:
[2024/03/19 22:18:17.316] 4:   {Unknown expression after the reported line}
[2024/03/19 22:18:17.316] 4: due to a fatal error condition:
[2024/03/19 22:18:17.316] 4:   SIGABRT - Abort (abnormal termination) signal
[2024/03/19 22:18:17.316] 4:
[2024/03/19 22:18:17.316] 4: Assertion failure: /data/mci/dc1805e3be04a52a82d59cd34dec2adf/realm-core/test/object-store/sync/flx_sync.cpp:1242
[2024/03/19 22:18:17.316] 4: 	 from expresion: '{Unknown expression after the reported line}'
[2024/03/19 22:18:17.316] 4: 	 with expansion: '{Unknown expression after the reported line}'
[2024/03/19 22:18:17.316] 4: 	 message: SIGABRT - Abort (abnormal termination) signal
[2024/03/19 22:18:17.316] 4:
[2024/03/19 22:18:17.316] 4: 0.000 s: flx: client reset
[2024/03/19 22:18:17.316] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=18, progress_server_version=4, locked_server_version=4, num_changesets=0)
[2024/03/19 22:18:17.316] 4: Realm.Sync.Client.Session - Connection[1]: Session[1]: Initiating deactivation
[2024/03/19 22:18:17.317] 4: realm-object-store-tests: src/catch2/reporters/catch_reporter_cumulative_base.cpp:133: virtual void Catch::CumulativeReporterBase::testCaseEnded(const Catch::TestCaseStats&): Assertion `m_sectionStack.size() == 0' failed.
[2024/03/19 22:18:17.317] 4: Realm.Sync.Client.Session - Connection[1]: Session[2]: Binding '/data/mci/dc1805e3be04a52a82d59cd34dec2adf/tmp/realm_Uvh5fk/realm.VvFo0Z.local' to ''
[2024/03/19 22:18:17.373] 1/1 Test #4: ObjectStoreTests-baas ............Subprocess aborted***Exception: 910.49 sec

@danieltabacaru
Copy link
Collaborator

@kiburtse Looking at the last logs, it seems the crash is after the download message is integrated. It could be that opening the realm was blocked until the integration was done, or came immediately after. We could try to time it like that and see if we can reproduce it.

@kiburtse
Copy link
Contributor Author

@kiburtse Looking at the last logs, it seems the crash is after the download message is integrated. It could be that opening the realm was blocked until the integration was done, or came immediately after. We could try to time it like that and see if we can reproduce it.

yeah, from what i can tell it also matches with my last comment here explaining how it happens. I've uploaded proposed straight forward fix, but do you have an idea how we could test it? I haven't found the way so far to trigger this exact situation in test.

@danieltabacaru
Copy link
Collaborator

I may have a way. My theory is that opening the realm being blocked is the interesting case. We need to keep that transaction open until update_schema blocks. We have some callbacks invoked from that transaction (IIRC) and so with the help of a promise we can prevent the commit until the other thread blocks.

@tgoyne
Copy link
Member

tgoyne commented Mar 25, 2024

That stack trace suggests that the very first time that a Transaction is being promoted to write for the ClientReplication instance it's advancing the read version. That's a normal and expected thing in multi-process usage, but should be impossible when only a single process is involved. We'll need to fix this for multi-process sync regardless, but being able to hit this currently points at another bug elsewhere.

@kiburtse
Copy link
Contributor Author

That stack trace suggests that the very first time that a Transaction is being promoted to write for the ClientReplication instance it's advancing the read version. That's a normal and expected thing in multi-process usage, but should be impossible when only a single process is involved. We'll need to fix this for multi-process sync regardless, but being able to hit this currently points at another bug elsewhere.

why should it be impossible in single process?

@tgoyne
Copy link
Member

tgoyne commented Mar 25, 2024

In order for there to be a new version to advance to, someone must have committed a write transaction, which requires having begun a write transaction. Therefore if beginning a write advances the read transaction, it cannot be the first time a write has been begun in that session. When multiple DB instances are involved the write producing the new version could have been made via a different DB instance, but there should only be one DB instance per file per process.

@danieltabacaru
Copy link
Collaborator

Another instance here

@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 24, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
3 participants