tuandinh0801
commented
1 year ago Same issue here. However, I think this relates to the server connection
Closed sync-by-unito[bot] closed 4 months ago
tuandinh0801
commented
1 year ago Same issue here. However, I think this relates to the server connection
kiburtse
commented
1 year ago relevant logs pieces:
kiburtse
commented
1 year ago potential fix is here #7042 according to @michael-wb
kiburtse
commented
1 year ago The fix was merged, and a few consistent failures are still present on multiple platforms:
[2023/11/09 00:05:35.366] 4: -------------------------------------------------------------------------------
[2023/11/09 00:05:35.366] 4: flx: compensating write errors get re-sent across sessions
[2023/11/09 00:05:35.366] 4: -------------------------------------------------------------------------------
[2023/11/09 00:05:35.366] 4: /System/Volumes/Data/data/mci/ce5606dee31a163804c97e6b77d90c49/realm-core/test/object-store/sync/flx_sync.cpp:3766
[2023/11/09 00:05:35.366] 4: ...............................................................................
[2023/11/09 00:05:35.366] 4:
[2023/11/09 00:05:35.367] 4: /System/Volumes/Data/data/mci/ce5606dee31a163804c97e6b77d90c49/realm-core/test/object-store/sync/flx_sync.cpp:3766: FAILED:
[2023/11/09 00:05:35.367] 4: {Unknown expression after the reported line}
[2023/11/09 00:05:35.367] 4: due to unexpected exception with message:
[2023/11/09 00:05:35.367] 4: wait_for_session() timed out
[2023/11/09 00:05:35.367] 4:
[2023/11/09 00:05:35.367] 4: Assertion failure: /System/Volumes/Data/data/mci/ce5606dee31a163804c97e6b77d90c49/realm-core/test/object-store/sync/flx_sync.cpp:3766
[2023/11/09 00:05:35.367] 4: from expresion: '{Unknown expression after the reported line}'
[2023/11/09 00:05:35.367] 4: with expansion: '{Unknown expression after the reported line}'
[2023/11/09 00:05:35.367] 4: message: wait_for_session() timed out
[2023/11/09 00:05:35.367] 4:
[2023/11/09 00:05:35.367] 4: 0.000 s: flx: compensating write errors get re-sent across sessionsSo, looks like baas update #7164 solved the issue with 'Test client migration and rollback with recovery' test failure, but some others are still happening, although also with some new issues:
[2023/11/29 00:38:36.997] 4: Connection[2]: Negotiated protocol version: 10
[2023/11/29 00:38:36.997] 4: Connection[2]: Connected to app services with request id: "6566880cdd540526833b4ee2"
[2023/11/29 00:38:36.998] 4: Connection[2]: Will emit a ping in 45857 milliseconds
[2023/11/29 00:38:36.998] 4: Connection[2]: Session[2]: Sending: BIND(session_ident=2, need_client_file_ident=false, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/29 00:38:36.999] 4: DB: 55945 Thread 7012: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/29 00:38:37.000] 4: DB: 55945 Thread 7012: Query found: 1, Duration: 126 us
[2023/11/29 00:38:37.000] 4: Connection[2]: Session[2]: Sending: IDENT(client_file_ident=34, client_file_ident_salt=4479223402983191206, scan_server_version=35, scan_client_version=5, latest_server_version=35, latest_server_version_salt=0, query_version=1, query_size=48, query="{"TopLevel":"(queryable_str_field == \"bizz\")"}")
[2023/11/29 00:38:37.009] 4: Connection[2]: Session[2]: Sending: MARK(request_ident=1)
[2023/11/29 00:38:37.009] 4: Connection[2]: Session[2]: Received: ERROR "Client attempted a write that is not allowed; it has been reverted" (error_code=231, is_fatal=false, error_action=Warning)
[2023/11/29 00:38:37.105] 4: Connection[2]: Download message compression: session_ident=2, is_body_compressed=false, compressed_body_size=52, uncompressed_body_size=52
[2023/11/29 00:38:37.106] 4: Connection[2]: Received: DOWNLOAD CHANGESET(session_ident=2, server_version=36, client_version=5, origin_timestamp=281147916934, origin_file_ident=1, original_changeset_size=26, changeset_size=26)
[2023/11/29 00:38:37.106] 4: Connection[2]: Session[2]: Received: DOWNLOAD(download_server_version=36, download_client_version=5, latest_server_version=36, latest_server_version_salt=779149815808681769, upload_client_version=16, upload_server_version=35, downloadable_bytes=0, last_in_batch=true, query_version=1, num_changesets=1, ...)
[2023/11/29 00:38:37.107] 4: Connection[2]: Session[2]: Finished changeset indexing (incoming: 1 changeset(s) / 1 instructions, local: 2 changeset(s) / 4 instructions, conflict group(s): 2)
[2023/11/29 00:38:37.108] 4: Connection[2]: Session[2]: Finished transforming 2 local changesets through 1 incoming changesets (4 vs 1 instructions, in 2 conflict groups)
[2023/11/29 00:38:37.111] 4: DB: 55945 Thread 7012: Initiate commit version: 19
[2023/11/29 00:38:37.111] 4: DB: 55945 Thread 7012: Commit of size 2472 done in 3330 us ref 10144
[2023/11/29 00:38:37.114] 4: Connection[2]: Session[2]: Integrated 1 changesets out of 1
[2023/11/29 00:38:37.114] 4: Connection[2]: Session[2]: 1 remote changeset integrated, producing client version 19
[2023/11/29 00:38:37.114] 4: Connection[2]: Session[2]: Reporting compensating write for client version 17 in server version 36: Client attempted a write that is not allowed; it has been reverted
[2023/11/29 00:38:37.115] 4: Connection[2]: Session[2]: Progress handler called, downloaded = 144, downloadable(total) = 144, uploaded = 121, uploadable = 263, reliable_download_progress = true, snapshot version = 19
[2023/11/29 00:38:37.116] 4: Connection[2]: Session[2]: Received: MARK(request_ident=1)
[2023/11/29 00:38:37.116] 4: DB: 55945 Thread 7012: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/29 00:38:37.117] 4: DB: 55945 Thread 7012: Query found: 0, Duration: 136 us
[2023/11/29 00:38:37.117] 4: Connection[2]: Session[2]: Sending: UPLOAD(progress_client_version=19, progress_server_version=36, locked_server_version=36, num_changesets=2)
[2023/11/29 00:38:37.118] 4: Connection[2]: Session[2]: Fetching changeset for upload (client_version=17, server_version=35, changeset_size=71, origin_timestamp=281147916897, origin_file_ident=0)
[2023/11/29 00:38:37.118] 4: Connection[2]: Session[2]: Fetching changeset for upload (client_version=18, server_version=35, changeset_size=71, origin_timestamp=281147916902, origin_file_ident=0)
[2023/11/29 00:38:37.120] 4: DB: 55945 Thread 7012: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/29 00:39:22.956] 4: DB: 55945 Thread 7012: Query found: 0, Duration: 113 us
[2023/11/29 00:39:22.956] 4: Connection[2]: Sending: PING(timestamp=5831564, rtt=0)
[2023/11/29 00:39:22.958] 4: Connection[2]: Received: PONG(timestamp=5831564)
[2023/11/29 00:39:22.958] 4: Connection[2]: Round trip time was 2 milliseconds
[2023/11/29 00:39:36.969] 4: Connection[2]: Will emit a ping in 57956 milliseconds
[2023/11/29 00:39:36.969] 4: ~TestFile() removing 'C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\tmp\rlm411C.tmp\realm.a06916' and 'C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\tmp\rlm411C.tmp'
[2023/11/29 00:39:36.971] 4: WARNING: ~TestFile() cleanup failed for 'C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\tmp\rlm411C.tmp\realm.a06916': The process cannot access the file because it is being used by another process.
[2023/11/29 00:39:36.998] 4: Waiting for 1 connections to drain
[2023/11/29 00:39:36.998] 4: Connection[2]: Session[2]: Initiating deactivation
[2023/11/29 00:39:36.999] 4: Connection[2]: Session[2]: Sending: UNBIND
[2023/11/29 00:39:36.999] 4: DB: 55945 Thread 7012: DB closed
[2023/11/29 00:39:37.000] 4: Draining connections during sync client shutdown
[2023/11/29 00:39:37.000] 4: Connection[2]: Session[2]: Deactivation completed
[2023/11/29 00:39:37.000] 4: Connection[2]: Force closed idle connection
[2023/11/29 00:39:37.000] 4: Connection[2]: Destroying connection object
[2023/11/29 00:39:37.080] 4:
[2023/11/29 00:39:37.080] 4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2023/11/29 00:39:37.080] 4: realm-object-store-tests.exe is a Catch2 v3.3.2 host application.
[2023/11/29 00:39:37.080] 4: Run with -? for options
[2023/11/29 00:39:37.080] 4:
[2023/11/29 00:39:37.080] 4: -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[2023/11/29 00:39:37.080] 4: flx: compensating write errors get re-sent across sessions
[2023/11/29 00:39:37.080] 4: -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
[2023/11/29 00:39:37.080] 4: C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\realm-core\test\object-store\sync\flx_sync.cpp(3763)
[2023/11/29 00:39:37.080] 4: ...........................................................................................................................................................................................................................................................................................................
[2023/11/29 00:39:37.080] 4:
[2023/11/29 00:39:37.080] 4: C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\realm-core\test\object-store\sync\flx_sync.cpp(3763): FAILED:
[2023/11/29 00:39:37.080] 4: {Unknown expression after the reported line}
[2023/11/29 00:39:37.080] 4: due to unexpected exception with message:
[2023/11/29 00:39:37.080] 4: wait_for_session() exceeded 60 ms
[2023/11/29 00:39:37.080] 4:
[2023/11/29 00:39:37.080] 4: Assertion failure: C:\data\mci\78eb2c2ac24c802f9308a22f4968079b\realm-core\test\object-store\sync\flx_sync.cpp(3763)
[2023/11/29 00:39:37.080] 4: from expresion: '{Unknown expression after the reported line}'
[2023/11/29 00:39:37.080] 4: with expansion: '{Unknown expression after the reported line}'
[2023/11/29 00:39:37.080] 4: message: wait_for_session() exceeded 60 ms
[2023/11/29 00:39:37.080] 4:
[2023/11/29 00:39:37.080] 4: 0.000 s: flx: compensating write errors get re-sent across sessionshanged on the very first object store baas test on nightly ubuntu2004-tsan
[2023/12/01 02:33:56.598] 4: Connection[1]: Negotiated protocol version: 10
[2023/12/01 02:33:56.598] 4: Connection[1]: Connected to app services with request id: "656946144a8aaae25f640add"
[2023/12/01 02:33:56.599] 4: Connection[1]: Will emit a ping in 53210 milliseconds
[2023/12/01 02:33:56.599] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/12/01 02:33:56.615] 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/12/01 02:33:56.615] 4: Connection[1]: Session[1]: Suspended
[2023/12/01 02:33:56.615] 4: Connection[1]: Session[1]: Will attempt to resume session after 1723 milliseconds
[2023/12/01 02:33:58.348] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/12/01 02:33:58.348] 4: Connection[1]: Session[1]: Resumed
[2023/12/01 02:33:58.348] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/12/01 02:33:58.365] 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/12/01 02:33:58.365] 4: Connection[1]: Session[1]: Suspended
[2023/12/01 02:33:58.365] 4: Connection[1]: Session[1]: Will attempt to resume session after 3379 milliseconds
[2023/12/01 02:33:58.365] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/12/01 02:34:01.752] 4: Connection[1]: Session[1]: Resumed
[2023/12/01 02:34:01.752] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/12/01 02:34:01.773] 4: Connection[1]: Session[1]: Received: IDENT(client_file_ident=34, client_file_ident_salt=6368679112160183267)
[2023/12/01 02:34:01.774] 4: DB: 45802 Thread 0x70000738f000: Initiate commit version: 7
[2023/12/01 02:34:01.774] 4: DB: 45802 Thread 0x70000738f000: Commit of size 1152 done in 917 us ref 6040
[2023/12/01 02:34:01.774] 4: DB: 45802 Thread 0x70000738f000: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/12/01 02:34:01.774] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 21 us
[2023/12/01 02:34:01.774] 4: Connection[1]: Session[1]: Sending: IDENT(client_file_ident=34, client_file_ident_salt=6368679112160183267, 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/12/01 02:34:01.795] 4: Connection[1]: Session[1]: Sending: MARK(request_ident=1)
[2023/12/01 02:34:01.795] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=135, uncompressed_body_size=135
[2023/12/01 02:34:01.795] 4: Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=11, client_version=0, origin_timestamp=281327641812, origin_file_ident=1, original_changeset_size=107, changeset_size=107)
[2023/12/01 02:34:01.795] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=11, download_client_version=0, latest_server_version=11, 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/12/01 02:34:01.795] 4: DB: 45802 Thread 0x70000738f000: Query find all: 'query_version != 0', limit = -1
[2023/12/01 02:34:01.795] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 6 us
[2023/12/01 02:34:01.795] 4: DB: 45802 Thread 0x70000738f000: Initiate commit version: 8
[2023/12/01 02:34:01.796] 4: DB: 45802 Thread 0x70000738f000: Commit of size 3768 done in 580 us ref 6520
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Created new pending bootstrap object for query version 0
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Finalized pending bootstrap object for query version 0
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 0. (changesets: 1, original total changeset size: 107)
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 4 instructions, local: 1 changeset(s) / 4 instructions, conflict group(s): 1)
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Finished transforming 1 local changesets through 1 incoming changesets (4 vs 4 instructions, in 1 conflict groups)
[2023/12/01 02:34:01.796] 4: Connection[1]: Session[1]: Removing pending bootstrap obj for query version 0
[2023/12/01 02:34:01.797] 4: DB: 45802 Thread 0x70000738f000: Initiate commit version: 9
[2023/12/01 02:34:01.797] 4: DB: 45802 Thread 0x70000738f000: Commit of size 3576 done in 549 us ref 6656
[2023/12/01 02:34:01.797] 4: Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2023/12/01 02:34:01.797] 4: Connection[1]: Session[1]: Integrated 1 changesets from pending bootstrap for query version 0, producing client version 9 in 1 ms. 0 changesets remaining in bootstrap
[2023/12/01 02:34:01.797] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 107, downloadable(total) = 107, uploaded = 0, uploadable = 110, reliable_download_progress = true, snapshot version = 9
[2023/12/01 02:34:01.797] 4: DB: 45802 Thread 0x70000738f000: Query find all: 'version < 0', limit = -1
[2023/12/01 02:34:01.797] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 4 us
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Initiate commit version: 10
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Commit of size 1608 done in 305 us ref 6832
[2023/12/01 02:34:01.798] 4: Connection[1]: Session[1]: Received: MARK(request_ident=1)
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 17 us
[2023/12/01 02:34:01.798] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=9, progress_server_version=11, locked_server_version=11, num_changesets=1)
[2023/12/01 02:34:01.798] 4: Connection[1]: Session[1]: Fetching changeset for upload (client_version=5, server_version=0, changeset_size=110, origin_timestamp=281327636563, origin_file_ident=0)
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 16 us
[2023/12/01 02:34:01.798] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=10, progress_server_version=11, locked_server_version=11, num_changesets=0)
[2023/12/01 02:34:01.798] 4: DB: 45802 Thread 0x70000738f000: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/12/01 02:34:49.814] 4: DB: 45802 Thread 0x70000738f000: Query found: 0, Duration: 10 us
[2023/12/01 02:34:49.814] 4: Connection[1]: Sending: PING(timestamp=70063656, rtt=0)
[2023/12/01 02:34:49.830] 4: Connection[1]: Received: PONG(timestamp=70063656)
[2023/12/01 02:34:49.830] 4: Connection[1]: Round trip time was 16 milliseconds
[2023/12/01 02:34:49.830] 4: Connection[1]: Will emit a ping in 57457 milliseconds
[2023/12/01 02:34:56.582] 4: Connection[1]: Session[1]: Initiating deactivation
[2023/12/01 02:34:56.582] 4: ~TestFile() removing '/data/mci/a3725f24782663f09b8c0188c8e71ed5/tmp/realm_zQjwFv/realm.IWfQyf' and '/data/mci/a3725f24782663f09b8c0188c8e71ed5/tmp/realm_zQjwFv'
[2023/12/01 02:34:56.582] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/12/01 02:34:56.583] 4: DB: 45802 Thread 0x70000738f000: DB closed
[2023/12/01 02:34:56.583] 4: Draining connections during sync client shutdown
[2023/12/01 02:34:56.583] 4: Connection[1]: Session[1]: Deactivation completed
[2023/12/01 02:34:56.583] 4: Waiting for 1 connections to drain
[2023/12/01 02:34:56.583] 4: Connection[1]: Force closed idle connection
[2023/12/01 02:34:56.639] 4: Connection[1]: Destroying connection object
[2023/12/01 02:34:56.639] 4:
[2023/12/01 02:34:56.639] 4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2023/12/01 02:34:56.639] 4: realm-object-store-tests is a Catch2 v3.3.2 host application.
[2023/12/01 02:34:56.639] 4: Run with -? for options
[2023/12/01 02:34:56.639] 4:
[2023/12/01 02:34:56.639] 4: -------------------------------------------------------------------------------
[2023/12/01 02:34:56.639] 4: flx: bootstraps contain all changes
[2023/12/01 02:34:56.639] 4: error/suspend between bootstrap and mark
[2023/12/01 02:34:56.639] 4: -------------------------------------------------------------------------------
[2023/12/01 02:34:56.639] 4: /System/Volumes/Data/data/mci/a3725f24782663f09b8c0188c8e71ed5/realm-core/test/object-store/sync/flx_sync.cpp:3548
[2023/12/01 02:34:56.639] 4: ...............................................................................
[2023/12/01 02:34:56.639] 4:
[2023/12/01 02:34:56.639] 4: /System/Volumes/Data/data/mci/a3725f24782663f09b8c0188c8e71ed5/realm-core/test/object-store/sync/flx_sync.cpp:3548: FAILED:
[2023/12/01 02:34:56.639] 4: {Unknown expression after the reported line}
[2023/12/01 02:34:56.639] 4: due to unexpected exception with message:
[2023/12/01 02:34:56.639] 4: wait_for_session() exceeded 60 ms
[2023/12/01 02:34:56.639] 4:
[2023/12/01 02:34:56.639] 4: Assertion failure: /System/Volumes/Data/data/mci/a3725f24782663f09b8c0188c8e71ed5/realm-core/test/object-store/sync/flx_sync.cpp:3548
[2023/12/01 02:34:56.639] 4: from expresion: '{Unknown expression after the reported line}'
[2023/12/01 02:34:56.639] 4: with expansion: '{Unknown expression after the reported line}'
[2023/12/01 02:34:56.639] 4: message: wait_for_session() exceeded 60 ms
[2023/12/01 02:34:56.639] 4:
[2023/12/01 02:34:56.639] 4: 60.023 s: error/suspend between bootstrap and mark
[2023/12/01 02:34:56.639] 4: 0.000 s: flx: bootstraps contain all changes[2023/11/27 22:09:05.271] 4: Connection[1]: Negotiated protocol version: 10
[2023/11/27 22:09:05.271] 4: Connection[1]: Connected to app services with request id: "65651381509a3636bb3010ed"
[2023/11/27 22:09:05.271] 4: Connection[1]: Will emit a ping in 27895 milliseconds
[2023/11/27 22:09:05.271] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/27 22:09:05.272] 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/27 22:09:05.272] 4: Connection[1]: Session[1]: Suspended
[2023/11/27 22:09:05.272] 4: Connection[1]: Session[1]: Will attempt to resume session after 1769 milliseconds
[2023/11/27 22:09:05.272] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/27 22:09:07.043] 4: Connection[1]: Session[1]: Resumed
[2023/11/27 22:09:07.043] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/27 22:09:07.044] 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/27 22:09:07.044] 4: Connection[1]: Session[1]: Suspended
[2023/11/27 22:09:07.045] 4: Connection[1]: Session[1]: Will attempt to resume session after 3076 milliseconds
[2023/11/27 22:09:10.124] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/27 22:09:10.124] 4: Connection[1]: Session[1]: Resumed
[2023/11/27 22:09:10.124] 4: Connection[1]: Session[1]: Sending: BIND(session_ident=1, need_client_file_ident=true, is_subserver=false, json_data="{"sessionReason":0}")
[2023/11/27 22:09:10.129] 4: Connection[1]: Session[1]: Received: IDENT(client_file_ident=34, client_file_ident_salt=1140497710258309572)
[2023/11/27 22:09:10.134] 4: DB: 31358 Thread 140388925179456: Initiate commit version: 9
[2023/11/27 22:09:10.134] 4: DB: 31358 Thread 140388925179456: Commit of size 1168 done in 5157 us ref 8312
[2023/11/27 22:09:10.135] 4: DB: 31358 Thread 140388925179456: Query find all: '(state == 3 or state == 6)', limit = -1
[2023/11/27 22:09:10.135] 4: DB: 31358 Thread 140388925179456: Query found: 0, Duration: 19 us
[2023/11/27 22:09:10.135] 4: Connection[1]: Session[1]: Sending: IDENT(client_file_ident=34, client_file_ident_salt=1140497710258309572, 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/27 22:09:10.139] 4: Connection[1]: Session[1]: Sending: MARK(request_ident=1)
[2023/11/27 22:09:10.139] 4: Connection[1]: Download message compression: session_ident=1, is_body_compressed=false, compressed_body_size=134, uncompressed_body_size=134
[2023/11/27 22:09:10.139] 4: Connection[1]: Received: DOWNLOAD CHANGESET(session_ident=1, server_version=4, client_version=0, origin_timestamp=281052550138, origin_file_ident=1, original_changeset_size=107, changeset_size=107)
[2023/11/27 22:09:10.139] 4: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=4, download_client_version=0, latest_server_version=4, 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/27 22:09:10.140] 4: DB: 31358 Thread 140388925179456: Query find all: 'query_version != 0', limit = -1
[2023/11/27 22:09:10.140] 4: DB: 31358 Thread 140388925179456: Query found: 0, Duration: 4 us
[2023/11/27 22:09:10.142] 4: DB: 31358 Thread 140388925179456: Initiate commit version: 10
[2023/11/27 22:09:10.142] 4: DB: 31358 Thread 140388925179456: Commit of size 3800 done in 1746 us ref 8536
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Created new pending bootstrap object for query version 0
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Finalized pending bootstrap object for query version 0
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Begin processing pending FLX bootstrap for query version 0. (changesets: 1, original total changeset size: 107)
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Finished changeset indexing (incoming: 1 changeset(s) / 4 instructions, local: 2 changeset(s) / 12 instructions, conflict group(s): 3)
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Finished transforming 2 local changesets through 1 incoming changesets (12 vs 4 instructions, in 3 conflict groups)
[2023/11/27 22:09:10.142] 4: Connection[1]: Session[1]: Removing pending bootstrap obj for query version 0
[2023/11/27 22:09:10.145] 4: DB: 31358 Thread 140388925179456: Initiate commit version: 11
[2023/11/27 22:09:10.145] 4: DB: 31358 Thread 140388925179456: Commit of size 3608 done in 2797 us ref 9200
[2023/11/27 22:09:10.145] 4: Connection[1]: Session[1]: Integrated 1 changesets out of 1
[2023/11/27 22:09:10.145] 4: 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
[2023/11/27 22:09:10.145] 4: Connection[1]: Session[1]: Progress handler called, downloaded = 107, downloadable(total) = 107, uploaded = 0, uploadable = 373, reliable_download_progress = true, snapshot version = 11
[2023/11/27 22:09:10.145] 4: DB: 31358 Thread 140388925179456: Query find all: 'version < 0', limit = -1
[2023/11/27 22:09:10.145] 4: DB: 31358 Thread 140388925179456: Query found: 0, Duration: 4 us
[2023/11/27 22:09:10.147] 4: DB: 31358 Thread 140388925179456: Initiate commit version: 12
[2023/11/27 22:09:10.147] 4: DB: 31358 Thread 140388925179456: Commit of size 1640 done in 1856 us ref 9776
[2023/11/27 22:09:10.147] 4: Connection[1]: Session[1]: Received: MARK(request_ident=1)
[2023/11/27 22:09:10.147] 4: DB: 31358 Thread 140388925179456: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/11/27 22:09:10.147] 4: DB: 31358 Thread 140388925179456: Query found: 1, Duration: 19 us
[2023/11/27 22:09:10.147] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=6, progress_server_version=0, locked_server_version=4, num_changesets=1)
[2023/11/27 22:09:10.147] 4: Connection[1]: Session[1]: Fetching changeset for upload (client_version=5, server_version=0, changeset_size=110, origin_timestamp=281052545257, origin_file_ident=0)
[2023/11/27 22:09:10.148] 4: DB: 31358 Thread 140388925179456: Query find all: 'version > 0 and (state == 1 or state == 2)', limit = -1
[2023/11/27 22:09:10.148] 4: DB: 31358 Thread 140388925179456: Query found: 1, Duration: 14 us
[2023/11/27 22:09:10.148] 4: Connection[1]: Session[1]: Sending: QUERY(query_version=1, query_size=30, query="{"TopLevel":"(TRUEPREDICATE)"}", snapshot_version=6)
[2023/11/27 22:09:10.148] 4: Connection[1]: Session[1]: Sending: MARK(request_ident=2)
[2023/11/27 22:09:10.148] 4: DB: 31358 Thread 140388925179456: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/27 22:09:10.148] 4: DB: 31358 Thread 140388925179456: Query found: 0, Duration: 12 us
[2023/11/27 22:09:10.148] 4: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=12, progress_server_version=4, locked_server_version=4, num_changesets=1)
[2023/11/27 22:09:10.148] 4: Connection[1]: Session[1]: Fetching changeset for upload (client_version=8, server_version=0, changeset_size=263, origin_timestamp=281052545269, origin_file_ident=0)
[2023/11/27 22:09:10.148] 4: DB: 31358 Thread 140388925179456: Query find all: 'version > 1 and (state == 1 or state == 2)', limit = -1
[2023/11/27 22:09:33.190] 4: DB: 31358 Thread 140388925179456: Query found: 0, Duration: 11 us
[2023/11/27 22:09:33.190] 4: Connection[1]: Sending: PING(timestamp=6213043, rtt=0)
[2023/11/27 22:09:33.191] 4: Connection[1]: Received: PONG(timestamp=6213043)
[2023/11/27 22:09:33.191] 4: Connection[1]: Round trip time was 0 milliseconds
[2023/11/27 22:09:33.191] 4: Connection[1]: Will emit a ping in 58741 milliseconds
[2023/11/27 22:10:05.271] 4: ~TestFile() removing '/data/mci/a204ab187981226cee96a321c906295f/tmp/realm_RngCyq/realm.DCY9vM' and '/data/mci/a204ab187981226cee96a321c906295f/tmp/realm_RngCyq'
[2023/11/27 22:10:05.271] 4: Connection[1]: Session[1]: Initiating deactivation
[2023/11/27 22:10:05.271] 4: Connection[1]: Session[1]: Sending: UNBIND
[2023/11/27 22:10:05.271] 4: Waiting for 1 connections to drain
[2023/11/27 22:10:05.271] 4: DB: 31358 Thread 140388925179456: DB closed
[2023/11/27 22:10:05.271] 4: Draining connections during sync client shutdown
[2023/11/27 22:10:05.271] 4: Connection[1]: Session[1]: Deactivation completed
[2023/11/27 22:10:05.271] 4: Connection[1]: Force closed idle connection
[2023/11/27 22:10:05.271] 4: Connection[1]: Destroying connection object
[2023/11/27 22:10:05.288] 4:
[2023/11/27 22:10:05.288] 4: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[2023/11/27 22:10:05.288] 4: realm-object-store-tests is a Catch2 v3.3.2 host application.
[2023/11/27 22:10:05.288] 4: Run with -? for options
[2023/11/27 22:10:05.288] 4:
[2023/11/27 22:10:05.288] 4: -------------------------------------------------------------------------------
[2023/11/27 22:10:05.288] 4: flx: writes work without waiting for sync
[2023/11/27 22:10:05.288] 4: -------------------------------------------------------------------------------
[2023/11/27 22:10:05.288] 4: /data/mci/a204ab187981226cee96a321c906295f/realm-core/test/object-store/sync/flx_sync.cpp:2336
[2023/11/27 22:10:05.288] 4: ...............................................................................
[2023/11/27 22:10:05.288] 4:
[2023/11/27 22:10:05.288] 4: /data/mci/a204ab187981226cee96a321c906295f/realm-core/test/object-store/sync/flx_sync.cpp:2336: FAILED:
[2023/11/27 22:10:05.288] 4: {Unknown expression after the reported line}
[2023/11/27 22:10:05.288] 4: due to unexpected exception with message:
[2023/11/27 22:10:05.288] 4: wait_for_session() exceeded 60 ms
[2023/11/27 22:10:05.288] 4:
[2023/11/27 22:10:05.288] 4: Assertion failure: /data/mci/a204ab187981226cee96a321c906295f/realm-core/test/object-store/sync/flx_sync.cpp:2336
[2023/11/27 22:10:05.288] 4: from expresion: '{Unknown expression after the reported line}'
[2023/11/27 22:10:05.288] 4: with expansion: '{Unknown expression after the reported line}'
[2023/11/27 22:10:05.288] 4: message: wait_for_session() exceeded 60 ms
[2023/11/27 22:10:05.288] 4:
[2023/11/27 22:10:05.288] 4: 0.000 s: flx: writes work without waiting for sync@jbreams @kmorkos could you take a look?
sync-by-unito[bot]
commented
1 year ago ➤ Jonathan Reams commented:
I'm working with the server team on this, it looks like some of our download acks are getting dropped or significantly delayed on the server but I don't know why yet. Will update here when we have more info.
sync-by-unito[bot]
commented
12 months ago ➤ Jonathan Reams commented:
I talked with [~kiro.morkos@mongodb.com] about these latest failures and it looks like the mongod server is getting stuck while trying to open a transaction in a few cases. We didn't have any great theories, but in the short term I've updated the mongod we use in evergreen to see if there was a mongo bug that may have been fixed in the last year that addresses these. If we see more of these wait_for_session timeouts I'll go back to troubleshooting this.
kiburtse
commented
11 months ago Looks like these failures went away after the upgrade to mongo server #7187. I think we can close it now. @jbreams is there still something you're investigating?
jbreams
commented
11 months ago Yup there are still timeouts going on, they're just way less frequent.
kiburtse
commented
11 months ago true, sigh.. "Test client migration and rollback with recovery" still times out on jenkins ci on latest 13.25.0
sync-by-unito[bot]
commented
6 months ago ➤ Jonathan Reams commented:
I think all the issues from when this was first reported have been resolved.
kiburtse
commented
5 months ago looks like it's still happening CI run for prepare 14.10.2
the test is flx: compensating write errors get re-sent across sessions
does this look like the same problem? client sends the upload, there is no reply from the server, then timeout
sync-by-unito[bot]
commented
4 months ago ➤ Jonathan Reams commented:
All the original issues from this ticket have been resolved.
Some of the object store baas tests have been failing during the wait_for_upload/wait_for_download/timed_sleeping_wait_for operations where the connection goes idle after an UPLOAD with no changesets, but the waiting thread is not notified.
I am thinking this may have been introduced by PR #7031, since this reduced some of the notifications on empty changesets, but not 100% sure.
The three failures in this test run were caused by this: https://spruce.mongodb.com/version/65315ea632f417d05a36f1c3/tasks?sorts=STATUS%3AASC%3BBASE_STATUS%3ADESC