CBL-2670

gistfile1.txt

22:39:19 	>>> Push large database
22:39:19 14:39:19.566564| [DB]: {DB#2202}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test.cblite2/db.sqlite3 @0x7f85faf211c0
22:39:19 14:39:19.566602| [DB]: {DB#2202} Opening database
22:39:19 14:39:19.569726| [DB]: {CollectionImpl#2203}==> litecore::CollectionImpl cbl_core_test/_default @0x7f85fad84cb0
22:39:19 14:39:19.569771| [DB]: {CollectionImpl#2203} Instantiated
22:39:19 14:39:19.570028| [DB]: {DB#2204}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test_2.cblite2/db.sqlite3 @0x7f85fad75ba0
22:39:19 14:39:19.570066| [DB]: {DB#2204} Opening database
22:39:19 14:39:19.572921| [DB]: {CollectionImpl#2205}==> litecore::CollectionImpl cbl_core_test_2/_default @0x7f85fad7f9a0
22:39:19 14:39:19.572965| [DB]: {CollectionImpl#2205} Instantiated
22:39:19 14:39:19.573048| Reading C/tests/data/iTunesMusicLibrary.json ...  
22:39:19 14:39:19.847628| Committing...
22:39:19 14:39:19.915237| [DB]: {DB#2206}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test.cblite2/db.sqlite3 @0x7f85fc905620
22:39:19 14:39:19.915292| [DB]: {DB#2206} Opening database
22:39:19 14:39:19.915804| [DB]: {CollectionImpl#2207}==> litecore::CollectionImpl cbl_core_test/_default @0x7f85fc911490
22:39:19 14:39:19.915865| [DB]: {CollectionImpl#2207} Instantiated
22:39:19 14:39:19.916089| [DB]: {DB#2208}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test_2.cblite2/db.sqlite3 @0x7f85fc911d20
22:39:19 14:39:19.916137| [DB]: {DB#2208} Opening database
22:39:19 14:39:19.916750| [DB]: {CollectionImpl#2209}==> litecore::CollectionImpl cbl_core_test_2/_default @0x7f85fc916770
22:39:19 14:39:19.916810| [DB]: {CollectionImpl#2209} Instantiated
22:39:19 14:39:19.917502| [Sync]: {Repl#2210}==> litecore::repl::Replicator /tmp/LiteCore_Tests_1638945514/cbl_core_test.cblite2/ ->ws://srv/ @0x7f85fe05a410
22:39:19 14:39:19.917545| [Sync]: {Repl#2210} Push=one-shot, Options={{}}
22:39:19 14:39:19.917918| [Sync]: {repl#2211}==> litecore::repl::Replicator /tmp/LiteCore_Tests_1638945514/cbl_core_test_2.cblite2/ <-ws://cli/ @0x7f85fb83b010
22:39:19 14:39:19.917954| [Sync]: {repl#2211} Push=passive, Pull=passive, Options={{}}
22:39:19 14:39:19.918058| Client replicator is {Repl#2210}
22:39:19 14:39:19.918107| Waiting for replication to complete...
22:39:19 14:39:19.969333| [Sync]: {repl#2211} Connected!
22:39:19 14:39:19.969440| [Sync]: {repl#2211} now busy
22:39:19 14:39:19.970561| [Sync]: {Repl#2210} No local checkpoint 'cp-4NkIXGGpNU2rTgpcgRZ/ZRyGeBo='
22:39:19 14:39:19.970679| [Sync]: {Repl#2210} Connected!
22:39:19 14:39:19.970897| [Sync]: {Repl#2210} now busy
22:39:19 14:39:19.971057| [Sync]: {Pusher#2212}==> litecore::repl::Pusher {Repl#2210} @0x7f85fc844f90
22:39:19 14:39:19.971360| [Sync]: {Pusher#2212} Starting push from local seq #1
22:39:19 14:39:19.971625| >> Replicator is busy, progress 0/0, 0 docs
22:39:19 14:39:19.980535| [Sync]: {Pusher#2212} Read 200 local changes up to #200: sending 'proposeChanges' with sequences #1 - #200
22:39:19 14:39:19.981654| [Sync]: {Pusher#2212} Read 200 local changes up to #400: sending 'proposeChanges' with sequences #201 - #400
22:39:19 14:39:19.982767| [Sync]: {Pusher#2212} Read 200 local changes up to #600: sending 'proposeChanges' with sequences #401 - #600
22:39:19 14:39:19.984049| [Sync]: {Pusher#2212} Read 200 local changes up to #800: sending 'proposeChanges' with sequences #601 - #800
22:39:19 14:39:19.985196| [Sync]: {Pusher#2212} Read 200 local changes up to #1000: sending 'proposeChanges' with sequences #801 - #1000
22:39:20 14:39:20.025003| [Sync]: {repl#2211} Request to get peer checkpoint 'cp-4NkIXGGpNU2rTgpcgRZ/ZRyGeBo='
22:39:20 14:39:20.038492| [Sync]: {revfinder#2213}==> litecore::repl::RevFinder {repl#2211} @0x7f85fc82e6c0
22:39:20 14:39:20.038661| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.040528| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2 w/request for 200 revs in 0.001727 sec
22:39:20 14:39:20.040712| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.042097| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#3 w/request for 200 revs in 0.001237 sec
22:39:20 14:39:20.098848| [Sync]: {Repl#2210} No remote checkpoint 'cp-4NkIXGGpNU2rTgpcgRZ/ZRyGeBo='
22:39:20 14:39:20.099102| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1)
22:39:20 14:39:20.100169| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 201)
22:39:20 14:39:20.101945| [Sync]: {Pusher#2212} Read 200 local changes up to #1200: sending 'proposeChanges' with sequences #1001 - #1200
22:39:20 14:39:20.103512| [Sync]: {Pusher#2212} Read 200 local changes up to #1400: sending 'proposeChanges' with sequences #1201 - #1400
22:39:20 14:39:20.167007| [DB]: {DB#2214}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test_2.cblite2/db.sqlite3 @0x7f85fadba260
22:39:20 14:39:20.167074| [DB]: {DB#2214} Opening database
22:39:20 14:39:20.167743| [DB]: {CollectionImpl#2215}==> litecore::CollectionImpl cbl_core_test_2/_default @0x7f85fadc9300
22:39:20 14:39:20.167787| [DB]: {CollectionImpl#2215} Instantiated
22:39:20 14:39:20.171073| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.171132| >> Replicator is busy, progress 0/712882, 0 docs
22:39:20 14:39:20.171382| [Sync]: {inserter#2216}==> litecore::repl::Inserter {repl#2211} @0x7f85fc8110e0
22:39:20 14:39:20.171444| [Sync]: {inserter#2216} Inserted 100 revs in   4.34ms (23058/sec) of which 95.5% was commit
22:39:20 14:39:20.172495| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4 w/request for 200 revs in 0.001388 sec
22:39:20 14:39:20.175349| [Sync]: {inserter#2216} Inserted 100 revs in   3.68ms (27191/sec) of which 88.8% was commit
22:39:20 14:39:20.178279| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.179044| [Sync]: {inserter#2216} Inserted 100 revs in   3.62ms (27608/sec) of which 88.3% was commit
22:39:20 14:39:20.179288| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#5 w/request for 200 revs in 0.000962 sec
22:39:20 14:39:20.183838| [Sync]: {inserter#2216} Inserted 100 revs in   4.63ms (21613/sec) of which 92.0% was commit
22:39:20 14:39:20.234706| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 401)
22:39:20 14:39:20.235564| [DB]: {DB#2217}==> litecore::SQLiteDataFile /tmp/LiteCore_Tests_1638945514/cbl_core_test.cblite2/db.sqlite3 @0x7f85fadca570
22:39:20 14:39:20.235618| [DB]: {DB#2217} Opening database
22:39:20 14:39:20.236344| [DB]: {CollectionImpl#2218}==> litecore::CollectionImpl cbl_core_test/_default @0x7f85fadbaf00
22:39:20 14:39:20.236495| [DB]: {CollectionImpl#2218} Instantiated
22:39:20 14:39:20.240432| [Sync]: {Pusher#2212} Read 200 local changes up to #1600: sending 'proposeChanges' with sequences #1401 - #1600
22:39:20 14:39:20.241083| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 601)
22:39:20 14:39:20.243932| [Sync]: {Pusher#2212} Read 200 local changes up to #1800: sending 'proposeChanges' with sequences #1601 - #1800
22:39:20 14:39:20.314548| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.315251| [Sync]: {inserter#2216} Inserted 100 revs in   3.66ms (27318/sec) of which 91.0% was commit
22:39:20 14:39:20.315534| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#6 w/request for 200 revs in 0.000924 sec
22:39:20 14:39:20.318910| [Sync]: {inserter#2216} Inserted 100 revs in   3.57ms (27978/sec) of which 87.6% was commit
22:39:20 14:39:20.321466| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.322032| [Sync]: {inserter#2216} Inserted 100 revs in   3.03ms (32973/sec) of which 92.6% was commit
22:39:20 14:39:20.322447| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#17 w/request for 200 revs in 0.000932 sec
22:39:20 14:39:20.326578| [Sync]: {inserter#2216} Inserted 100 revs in   4.44ms (22525/sec) of which 91.9% was commit
22:39:20 14:39:20.378196| >> Replicator is busy, progress 203448/909512, 400 docs
22:39:20 14:39:20.379553| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 801)
22:39:20 14:39:20.382521| [Sync]: {Pusher#2212} Read 200 local changes up to #2000: sending 'proposeChanges' with sequences #1801 - #2000
22:39:20 14:39:20.383680| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1001)
22:39:20 14:39:20.386481| [Sync]: {Pusher#2212} Read 200 local changes up to #2200: sending 'proposeChanges' with sequences #2001 - #2200
22:39:20 14:39:20.445726| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.446449| [Sync]: {inserter#2216} Inserted 100 revs in   3.84ms (26025/sec) of which 90.9% was commit
22:39:20 14:39:20.446856| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#21 w/request for 200 revs in 0.001074 sec
22:39:20 14:39:20.450257| [Sync]: {inserter#2216} Inserted 100 revs in   3.59ms (27856/sec) of which 87.2% was commit
22:39:20 14:39:20.453163| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.453880| [Sync]: {inserter#2216} Inserted 100 revs in   3.48ms (28706/sec) of which 89.6% was commit
22:39:20 14:39:20.454016| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#419 w/request for 200 revs in 0.000805 sec
22:39:20 14:39:20.458412| [Sync]: {inserter#2216} Inserted 100 revs in   4.42ms (22631/sec) of which 90.7% was commit
22:39:20 14:39:20.499414| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1201)
22:39:20 14:39:20.502338| [Sync]: {Pusher#2212} Read 200 local changes up to #2400: sending 'proposeChanges' with sequences #2201 - #2400
22:39:20 14:39:20.503647| [Sync]: {Pusher#2212} Checkpoint now [0-1000]
22:39:20 14:39:20.504735| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1401)
22:39:20 14:39:20.506717| [Sync]: {Pusher#2212} Read 200 local changes up to #2600: sending 'proposeChanges' with sequences #2401 - #2600
22:39:20 14:39:20.569400| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.570161| [Sync]: {inserter#2216} Inserted 100 revs in   4.30ms (23245/sec) of which 93.5% was commit
22:39:20 14:39:20.570446| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#430 w/request for 200 revs in 0.000983 sec
22:39:20 14:39:20.573758| [Sync]: {inserter#2216} Inserted 100 revs in   3.40ms (29449/sec) of which 94.1% was commit
22:39:20 14:39:20.576236| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.576826| [Sync]: {inserter#2216} Inserted 100 revs in   2.95ms (33907/sec) of which 85.0% was commit
22:39:20 14:39:20.577301| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#821 w/request for 200 revs in 0.001017 sec
22:39:20 14:39:20.580973| >> Replicator is busy, progress 609776/1315850, 1200 docs
22:39:20 14:39:20.581219| [Sync]: {inserter#2216} Inserted 100 revs in   4.27ms (23417/sec) of which 90.6% was commit
22:39:20 14:39:20.635760| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1601)
22:39:20 14:39:20.638426| [Sync]: {Pusher#2212} Read 200 local changes up to #2800: sending 'proposeChanges' with sequences #2601 - #2800
22:39:20 14:39:20.639267| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 1801)
22:39:20 14:39:20.642146| [Sync]: {Pusher#2212} Read 200 local changes up to #3000: sending 'proposeChanges' with sequences #2801 - #3000
22:39:20 14:39:20.706085| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.706558| [Sync]: {inserter#2216} Inserted 100 revs in   3.36ms (29722/sec) of which 89.5% was commit
22:39:20 14:39:20.707506| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#832 w/request for 200 revs in 0.001350 sec
22:39:20 14:39:20.710133| [Sync]: {inserter#2216} Inserted 100 revs in   3.20ms (31205/sec) of which 90.4% was commit
22:39:20 14:39:20.712727| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.713254| [Sync]: {inserter#2216} Inserted 100 revs in   3.00ms (33286/sec) of which 88.1% was commit
22:39:20 14:39:20.713729| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#1223 w/request for 200 revs in 0.000951 sec
22:39:20 14:39:20.717356| [Sync]: {inserter#2216} Inserted 100 revs in   3.99ms (25069/sec) of which 91.3% was commit
22:39:20 14:39:20.770951| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 2001)
22:39:20 14:39:20.773906| [Sync]: {Pusher#2212} Read 200 local changes up to #3200: sending 'proposeChanges' with sequences #3001 - #3200
22:39:20 14:39:20.774619| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 2201)
22:39:20 14:39:20.774959| [Sync]: {Pusher#2212} Checkpoint now [0-2000]
22:39:20 14:39:20.777688| [Sync]: {Pusher#2212} Read 200 local changes up to #3400: sending 'proposeChanges' with sequences #3201 - #3400
22:39:20 14:39:20.781018| >> Replicator is busy, progress 1013028/1720490, 2000 docs
22:39:20 14:39:20.839548| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.839818| [Sync]: {inserter#2216} Inserted 100 revs in   3.18ms (31485/sec) of which 92.7% was commit
22:39:20 14:39:20.840742| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#1258 w/request for 200 revs in 0.001131 sec
22:39:20 14:39:20.843412| [Sync]: {inserter#2216} Inserted 100 revs in   3.39ms (29516/sec) of which 94.2% was commit
22:39:20 14:39:20.846246| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.846939| [Sync]: {inserter#2216} Inserted 100 revs in   3.40ms (29422/sec) of which 85.8% was commit
22:39:20 14:39:20.847209| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#1625 w/request for 200 revs in 0.000914 sec
22:39:20 14:39:20.851364| [Sync]: {inserter#2216} Inserted 100 revs in   4.23ms (23619/sec) of which 90.9% was commit
22:39:20 14:39:20.902307| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 2401)
22:39:20 14:39:20.905394| [Sync]: {Pusher#2212} Read 200 local changes up to #3600: sending 'proposeChanges' with sequences #3401 - #3600
22:39:20 14:39:20.906101| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 2601)
22:39:20 14:39:20.909013| [Sync]: {Pusher#2212} Read 200 local changes up to #3800: sending 'proposeChanges' with sequences #3601 - #3800
22:39:20 14:39:20.971755| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.972170| [Sync]: {inserter#2216} Inserted 100 revs in   3.56ms (28071/sec) of which 93.3% was commit
22:39:20 14:39:20.972879| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#1636 w/request for 200 revs in 0.001063 sec
22:39:20 14:39:20.975638| [Sync]: {inserter#2216} Inserted 100 revs in   3.27ms (30583/sec) of which 94.3% was commit
22:39:20 14:39:20.978294| [Sync]: {revfinder#2213} Received 200 changes
22:39:20 14:39:20.978919| [Sync]: {inserter#2216} Inserted 100 revs in   3.18ms (31453/sec) of which 86.9% was commit
22:39:20 14:39:20.979303| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2027 w/request for 200 revs in 0.000959 sec
22:39:20 14:39:20.981102| >> Replicator is busy, progress 1212500/1929152, 2400 docs
22:39:20 14:39:20.983389| [Sync]: {inserter#2216} Inserted 100 revs in   4.31ms (23195/sec) of which 91.8% was commit
22:39:21 14:39:21.024150| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 2801)
22:39:21 14:39:21.026465| [Sync]: {Pusher#2212} Read 200 local changes up to #4000: sending 'proposeChanges' with sequences #3801 - #4000
22:39:21 14:39:21.030080| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 3001)
22:39:21 14:39:21.032470| [Sync]: {Pusher#2212} Read 200 local changes up to #4200: sending 'proposeChanges' with sequences #4001 - #4200
22:39:21 14:39:21.089704| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.090394| [Sync]: {inserter#2216} Inserted 100 revs in   3.72ms (26864/sec) of which 91.4% was commit
22:39:21 14:39:21.091036| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2038 w/request for 200 revs in 0.001269 sec
22:39:21 14:39:21.093856| [Sync]: {inserter#2216} Inserted 100 revs in   3.35ms (29873/sec) of which 89.7% was commit
22:39:21 14:39:21.096715| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.097361| [Sync]: {inserter#2216} Inserted 100 revs in   3.41ms (29300/sec) of which 83.6% was commit
22:39:21 14:39:21.097800| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2429 w/request for 200 revs in 0.001036 sec
22:39:21 14:39:21.101971| [Sync]: {inserter#2216} Inserted 100 revs in   4.43ms (22565/sec) of which 93.9% was commit
22:39:21 14:39:21.145828| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 3201)
22:39:21 14:39:21.147805| [Sync]: {Pusher#2212} Read 200 local changes up to #4400: sending 'proposeChanges' with sequences #4201 - #4400
22:39:21 14:39:21.148241| [Sync]: {Pusher#2212} Checkpoint now [0-3000]
22:39:21 14:39:21.149212| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 3401)
22:39:21 14:39:21.151270| [Sync]: {Pusher#2212} Read 200 local changes up to #4600: sending 'proposeChanges' with sequences #4401 - #4600
22:39:21 14:39:21.198431| >> Replicator is busy, progress 1621390/2336338, 3200 docs
22:39:21 14:39:21.214009| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.214524| [Sync]: {inserter#2216} Inserted 100 revs in   3.47ms (28820/sec) of which 94.8% was commit
22:39:21 14:39:21.215372| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2440 w/request for 200 revs in 0.001300 sec
22:39:21 14:39:21.218052| [Sync]: {inserter#2216} Inserted 100 revs in   3.40ms (29384/sec) of which 88.4% was commit
22:39:21 14:39:21.220867| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.221335| [Sync]: {inserter#2216} Inserted 100 revs in   3.19ms (31311/sec) of which 87.5% was commit
22:39:21 14:39:21.221959| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2831 w/request for 200 revs in 0.001042 sec
22:39:21 14:39:21.225813| [Sync]: {inserter#2216} Inserted 100 revs in   4.40ms (22713/sec) of which 91.4% was commit
22:39:21 14:39:21.278636| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 3601)
22:39:21 14:39:21.281443| [Sync]: {Pusher#2212} Read 200 local changes up to #4800: sending 'proposeChanges' with sequences #4601 - #4800
22:39:21 14:39:21.282061| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 3801)
22:39:21 14:39:21.284845| [Sync]: {Pusher#2212} Read 200 local changes up to #5000: sending 'proposeChanges' with sequences #4801 - #5000
22:39:21 14:39:21.358520| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.359681| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#2888 w/request for 200 revs in 0.001099 sec
22:39:21 14:39:21.367126| [Sync]: {inserter#2216} Inserted 100 revs in  11.58ms ( 8635/sec) of which 96.4% was commit
22:39:21 14:39:21.370712| [Sync]: {inserter#2216} Inserted 100 revs in   3.46ms (28913/sec) of which 88.5% was commit
22:39:21 14:39:21.373640| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.374158| [Sync]: {inserter#2216} Inserted 100 revs in   3.36ms (29741/sec) of which 87.7% was commit
22:39:21 14:39:21.374829| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#3233 w/request for 200 revs in 0.001137 sec
22:39:21 14:39:21.378641| [Sync]: {inserter#2216} Inserted 100 revs in   4.38ms (22828/sec) of which 93.3% was commit
22:39:21 14:39:21.423716| >> Replicator is busy, progress 1825684/2538858, 3600 docs
22:39:21 14:39:21.423827| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 4001)
22:39:21 14:39:21.426474| [Sync]: {Pusher#2212} Read 200 local changes up to #5200: sending 'proposeChanges' with sequences #5001 - #5200
22:39:21 14:39:21.427945| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 4201)
22:39:21 14:39:21.430626| [Sync]: {Pusher#2212} Read 200 local changes up to #5400: sending 'proposeChanges' with sequences #5201 - #5400
22:39:21 14:39:21.431351| [Sync]: {Pusher#2212} Checkpoint now [0-4000]
22:39:21 14:39:21.494424| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.495034| [Sync]: {inserter#2216} Inserted 100 revs in   3.70ms (27051/sec) of which 92.0% was commit
22:39:21 14:39:21.495554| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#3245 w/request for 200 revs in 0.001049 sec
22:39:21 14:39:21.498731| [Sync]: {inserter#2216} Inserted 100 revs in   3.62ms (27626/sec) of which 90.2% was commit
22:39:21 14:39:21.501600| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.502051| [Sync]: {inserter#2216} Inserted 100 revs in   3.24ms (30911/sec) of which 89.3% was commit
22:39:21 14:39:21.502573| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#3635 w/request for 200 revs in 0.000918 sec
22:39:21 14:39:21.506709| [Sync]: {inserter#2216} Inserted 100 revs in   4.53ms (22054/sec) of which 94.2% was commit
22:39:21 14:39:21.558894| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 4401)
22:39:21 14:39:21.561902| [Sync]: {Pusher#2212} Read 200 local changes up to #5600: sending 'proposeChanges' with sequences #5401 - #5600
22:39:21 14:39:21.562583| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 4601)
22:39:21 14:39:21.565544| [Sync]: {Pusher#2212} Read 200 local changes up to #5800: sending 'proposeChanges' with sequences #5601 - #5800
22:39:21 14:39:21.632319| >> Replicator is busy, progress 2232274/2944556, 4400 docs
22:39:21 14:39:21.638112| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.638653| [Sync]: {inserter#2216} Inserted 100 revs in   3.51ms (28459/sec) of which 89.5% was commit
22:39:21 14:39:21.639385| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#3646 w/request for 200 revs in 0.001181 sec
22:39:21 14:39:21.642480| [Sync]: {inserter#2216} Inserted 100 revs in   3.64ms (27491/sec) of which 92.9% was commit
22:39:21 14:39:21.645323| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.645960| [Sync]: {inserter#2216} Inserted 100 revs in   3.38ms (29614/sec) of which 86.2% was commit
22:39:21 14:39:21.646508| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4037 w/request for 200 revs in 0.001136 sec
22:39:21 14:39:21.650088| [Sync]: {inserter#2216} Inserted 100 revs in   4.00ms (25015/sec) of which 91.9% was commit
22:39:21 14:39:21.700987| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 4801)
22:39:21 14:39:21.703769| [Sync]: {Pusher#2212} Read 200 local changes up to #6000: sending 'proposeChanges' with sequences #5801 - #6000
22:39:21 14:39:21.704540| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 5001)
22:39:21 14:39:21.707422| [Sync]: {Pusher#2212} Read 200 local changes up to #6200: sending 'proposeChanges' with sequences #6001 - #6200
22:39:21 14:39:21.769828| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.770316| [Sync]: {inserter#2216} Inserted 100 revs in   3.12ms (32090/sec) of which 86.9% was commit
22:39:21 14:39:21.770819| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4047 w/request for 200 revs in 0.000920 sec
22:39:21 14:39:21.773851| [Sync]: {inserter#2216} Inserted 100 revs in   3.41ms (29302/sec) of which 93.0% was commit
22:39:21 14:39:21.776513| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.776854| [Sync]: {inserter#2216} Inserted 100 revs in   2.93ms (34111/sec) of which 88.8% was commit
22:39:21 14:39:21.777307| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4439 w/request for 200 revs in 0.000747 sec
22:39:21 14:39:21.780913| [Sync]: {inserter#2216} Inserted 100 revs in   3.98ms (25151/sec) of which 90.0% was commit
22:39:21 14:39:21.832443| >> Replicator is busy, progress 2475436/3153748, 4877 docs
22:39:21 14:39:21.832596| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 5201)
22:39:21 14:39:21.832878| >> Replicator is busy, progress 2487028/3153748, 4900 docs
22:39:21 14:39:21.835529| [Sync]: {Pusher#2212} Read 200 local changes up to #6400: sending 'proposeChanges' with sequences #6201 - #6400
22:39:21 14:39:21.835835| [Sync]: {Pusher#2212} Checkpoint now [0-5000]
22:39:21 14:39:21.836366| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 5401)
22:39:21 14:39:21.839577| [Sync]: {Pusher#2212} Read 200 local changes up to #6600: sending 'proposeChanges' with sequences #6401 - #6600
22:39:21 14:39:21.901541| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.901924| [Sync]: {inserter#2216} Inserted 100 revs in   3.48ms (28768/sec) of which 92.4% was commit
22:39:21 14:39:21.902675| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4450 w/request for 200 revs in 0.001069 sec
22:39:21 14:39:21.905139| [Sync]: {inserter#2216} Inserted 100 revs in   3.13ms (31977/sec) of which 94.3% was commit
22:39:21 14:39:21.907804| [Sync]: {revfinder#2213} Received 200 changes
22:39:21 14:39:21.908316| [Sync]: {inserter#2216} Inserted 100 revs in   3.09ms (32390/sec) of which 85.2% was commit
22:39:21 14:39:21.908924| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4841 w/request for 200 revs in 0.001071 sec
22:39:21 14:39:21.911787| [Sync]: {inserter#2216} Inserted 100 revs in   3.39ms (29504/sec) of which 96.6% was commit
22:39:21 14:39:21.965595| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 5601)
22:39:21 14:39:21.976994| [Sync]: {Pusher#2212} Read 200 local changes up to #6800: sending 'proposeChanges' with sequences #6601 - #6800
22:39:21 14:39:21.977613| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 5801)
22:39:21 14:39:21.980758| [Sync]: {Pusher#2212} Read 200 local changes up to #7000: sending 'proposeChanges' with sequences #6801 - #7000
22:39:22 14:39:22.038461| >> Replicator is busy, progress 2844784/3555934, 5600 docs
22:39:22 14:39:22.038612| >> Replicator is busy, progress 2844784/3555934, 5600 docs
22:39:22 14:39:22.044026| [Sync]: {revfinder#2213} Received 200 changes
22:39:22 14:39:22.044591| [Sync]: {inserter#2216} Inserted 100 revs in   3.52ms (28406/sec) of which 89.4% was commit
22:39:22 14:39:22.045287| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#4852 w/request for 200 revs in 0.001200 sec
22:39:22 14:39:22.048081| [Sync]: {inserter#2216} Inserted 100 revs in   3.39ms (29509/sec) of which 90.7% was commit
22:39:22 14:39:22.050964| [Sync]: {revfinder#2213} Received 200 changes
22:39:22 14:39:22.051492| [Sync]: {inserter#2216} Inserted 100 revs in   3.32ms (30099/sec) of which 88.6% was commit
22:39:22 14:39:22.052009| [Sync]: {revfinder#2213} Responded to 'proposeChanges' REQ#5243 w/request for 200 revs in 0.000996 sec
22:39:22 14:39:22.056053| [Sync]: {inserter#2216} Inserted 100 revs in   4.44ms (22524/sec) of which 93.8% was commit
22:39:22 14:39:22.106545| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 6001)
22:39:22 14:39:22.109680| [Sync]: {Pusher#2212} Read 200 local changes up to #7200: sending 'proposeChanges' with sequences #7001 - #7200
22:39:22 14:39:22.110371| [Sync]: {Pusher#2212} Got response for 200 local changes (sequences from 6201)
22:39:22 14:39:22.110866| [Sync]: {Pusher#2212} Checkpoint now [0-6000]
22:39:22 14:39:22.113602| [Sync]: {Pusher#2212} Read 200 local changes up to #7400: sending 'proposeChanges' with sequences #7201 - #7400
22:39:22 14:39:22.171687| [BLIP]: {BLIPIO#2219}==> litecore::blip::BLIPIO <-ws://cli/ @0x7f85fc8453d0
22:39:22 14:39:22.171788| [BLIP] ERROR: {BLIPIO#2219} Caught exception handling incoming BLIP message: BLIP protocol error: Bad incoming REQ #6042 (too high)
22:39:22 14:39:22.171886| WARNING: Caught unexpected C++ runtime_error("BLIP protocol error: Bad incoming REQ #6042 (too high)")
22:39:22 14:39:22.172527| [Sync]: {repl#2211} Connection closed with Exception 10: "BLIP protocol error: Bad incoming REQ #6042 (too high)" (state=2)
22:39:22 14:39:22.172864| [Sync] ERROR: {repl#2211} Got LiteCore error: LiteCore UnexpectedError, "BLIP protocol error: Bad incoming REQ #6042 (too high)"
22:39:22 14:39:22.173615| [Sync] ERROR: {repl#2211} Stopping due to fatal error: LiteCore UnexpectedError, "BLIP protocol error: Bad incoming REQ #6042 (too high)"
22:39:22 14:39:22.199702| [Sync]: {inserter#2216} Inserted   4 revs in   0.64ms ( 6283/sec) of which 88.6% was commit
22:39:22 14:39:22.235139| [Sync]: {Repl#2210} Connection closed with WebSocket/HTTP status 1011: "Unexpected exception" (state=2)
22:39:22 14:39:22.235277| [Sync] ERROR: {Repl#2210} Got LiteCore error: WebSocket error 1011, "Unexpected exception"
22:39:22 14:39:22.235387| >> Replicator closed with code=0/1011, message=Unexpected exception
22:39:22 14:39:22.236650| [Sync]: BLIP sent 6438 msgs (1300796 bytes), rcvd 0 msgs (48302 bytes) in 2.267 sec. Max outbox depth was 1, avg 1.00
22:39:22 14:39:22.253241| >> Replicator is busy, progress 3101254/3762574, 6000 docs
22:39:22 14:39:22.253388| [Sync]: {Repl#2210} now stopped
22:39:22 14:39:22.253450| [Sync]: {repl#2211} now stopped
22:39:22 14:39:22.254471| [Sync]: BLIP sent 6033 msgs (48302 bytes), rcvd 6040 msgs (1222625 bytes) in 2.285 sec. Max outbox depth was 1, avg 1.00
22:39:22 14:39:22.256921| [DB]: {DB#2217} Closing database
22:39:22 14:39:22.256983| [DB]: {CollectionImpl#2218} Closed
22:39:22 14:39:22.257024| >> Replicator is stopped, progress 3101254/3762574, 6000 docs
22:39:22 14:39:22.257107| [DB]: {DB#2214} Closing database
22:39:22 14:39:22.257187| [DB]: {CollectionImpl#2215} Closed
22:39:22 14:39:22.257349| >>> Replication complete (2.339 sec) <<<
22:39:22 
22:39:22 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
22:39:22 CppTests is a Catch v2.13.3 host application.
22:39:22 Run with -? for options
22:39:22 
22:39:22 

-----------------------------------------------------------------------------------------------------------------------
22:39:22 Push large database
22:39:22 

-----------------------------------------------------------------------------------------------------------------------
22:39:22 /Users/****/workspace/****-lite-core-macosx/****-lite-core/Replicator/tests/ReplicatorLoopbackTest.cc:226
22:39:22 .......................................................................................................................
22:39:22 
22:39:22 /Users/****/workspace/****-lite-core-macosx/****-lite-core/LiteCore/tests/../../Replicator/tests/ReplicatorLoopbackTest.hh:144: FAILED:
22:39:22   CHECK( _statusReceived.error.code == _expectedError.code )
22:39:22 with expansion:
22:39:22   1011 (0x3f3) == 0
22:39:22 
22:39:22 /Users/****/workspace/****-lite-core-macosx/****-lite-core/LiteCore/tests/../../Replicator/tests/ReplicatorLoopbackTest.hh:153: FAILED:
22:39:22   CHECK( _statusReceived.progress.unitsCompleted == _statusReceived.progress.unitsTotal )
22:39:22 with expansion:
22:39:22   3101254 (0x2f5246) == 3762574 (0x39698e)
22:39:22 
22:39:22 /Users/****/workspace/****-lite-core-macosx/****-lite-core/LiteCore/tests/../../Replicator/tests/ReplicatorLoopbackTest.hh:157: FAILED:
22:39:22   CHECK( _statusReceived.progress.documentCount == uint64_t(_expectedDocumentCount) )
22:39:22 with expansion:
22:39:22   6000 (0x1770) == 12189 (0x2f9d)
22:39:22 
22:39:22 14:39:22.257844| [DB]: {DB#2208} Closing database
22:39:22 14:39:22.257897| [DB]: {CollectionImpl#2209} Closed
22:39:22 14:39:22.258240| [DB]: {DB#2206} Closing database
22:39:22 14:39:22.258264| [DB]: {CollectionImpl#2207} Closed
22:39:22 14:39:22.258316| >> Comparing databases...
22:39:22 /Users/****/workspace/****-lite-core-macosx/****-lite-core/LiteCore/tests/../../Replicator/tests/ReplicatorLoopbackTest.hh:517: FAILED:
22:39:22   REQUIRE( ok )
22:39:22 with expansion:
22:39:22   ****
22:39:22 with message:
22:39:22   db document #6004: '0006005'
22:39:22 
22:39:22 14:39:22.397786| [DB]: {DB#2204} Closing database
22:39:22 14:39:22.397847| [DB]: Deleting database file /private/tmp/LiteCore_Tests_1638945514/cbl_core_test_2.cblite2/db.sqlite3 (with -wal and -shm)
22:39:22 14:39:22.398325| [DB]: {CollectionImpl#2205} Closed
22:39:22 14:39:22.402690| [DB]: {DB#2202} Closing database
22:39:22 14:39:22.402741| [DB]: Deleting database file /private/tmp/LiteCore_Tests_1638945514/cbl_core_test.cblite2/db.sqlite3 (with -wal and -shm)
22:39:22 14:39:22.403370| [DB]: {CollectionImpl#2203} Closed
22:39:22 	    [2.83719 sec]