zadam / trilium

Build your personal knowledge base with Trilium Notes
GNU Affero General Public License v3.0
27.2k stars 1.9k forks source link

(Bug report) TypeError: Cannot read properties of undefined (reading 'length') #2499

Closed sigaloid closed 2 years ago

sigaloid commented 2 years ago

Trilium Version

0.49.1-beta

What operating system are you using?

Other Linux

What is your setup?

Local + server sync

Operating System Version

Fedora

Description

matt@fedora ~> trilium
DB size: 4460 KB
Becca (note cache) load took 1ms
App HTTP server starting up at port 37840
{
  "appVersion": "0.49.1-beta",
  "dbVersion": 188,
  "syncVersion": 23,
  "buildDate": "2021-12-24T23:05:10+01:00",
  "buildRevision": "0217b1c85de9a2824e7f07d07a357064c5803383",
  "dataDirectory": "/home/matt/.local/share/trilium-data",
  "clipperProtocolVersion": "1.0"
}
CPU model: AMD Ryzen 5 1600 Six-Core Processor, logical cores: 12 freq: 3502 Mhz
Listening on port 37840
Registered global shortcut Ctrl+Alt+P for action createNoteIntoInbox
libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
[244861:0101/133426.786519:ERROR:sandbox_linux.cc(376)] InitializeSandbox() called with multiple threads in process gpu-process.
Generated CSRF token 2EnILUxp-6E9juXqhAYFEW76UsrKOBEdAeP8 with secret _csrf=cxUPLWbyiojO-2updacTo9Zb; Path=/
200 GET /api/options with 5275 bytes took 1ms
GET /api/tree returned 404 with response "Note root not found in the cache"
404 GET /api/tree with 32 bytes took 1ms
200 GET /api/keyboard-actions with 11944 bytes took 1ms
200 GET /api/keyboard-shortcuts-for-notes with 2 bytes took 0ms
200 GET /api/script/widgets with 2 bytes took 1ms
websocket client connected
Table counts: notes: 0, note_revisions: 28, branches: 0, attributes: 0, api_tokens: 0
TypeError: Cannot read properties of undefined (reading 'length')
    at ConsistencyChecks.checkTreeCycles (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:90:36)
    at ConsistencyChecks.runAllChecksAndFixers (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:646:18)
    at /usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:676:18
    at Object.doExclusively (/usr/lib/trilium/resources/app.asar/src/services/sync_mutex.js:13:22)
    at async ConsistencyChecks.runChecks (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:671:9)
TypeError: Cannot read properties of undefined (reading 'length')
    at ConsistencyChecks.checkTreeCycles (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:90:36)
    at ConsistencyChecks.runAllChecksAndFixers (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:646:18)
    at /usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:676:18
    at Object.doExclusively (/usr/lib/trilium/resources/app.asar/src/services/sync_mutex.js:13:22)
    at async ConsistencyChecks.runChecks (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:671:9)
(node:244823) UnhandledPromiseRejectionWarning: TypeError: Cannot read properties of undefined (reading 'length')
    at ConsistencyChecks.checkTreeCycles (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:90:36)
    at ConsistencyChecks.runAllChecksAndFixers (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:646:18)
    at /usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:676:18
    at Object.doExclusively (/usr/lib/trilium/resources/app.asar/src/services/sync_mutex.js:13:22)
    at async ConsistencyChecks.runChecks (/usr/lib/trilium/resources/app.asar/src/services/consistency_checks.js:671:9)
(Use `trilium --trace-warnings ...` to show where the warning was created)
(node:244823) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
Nothing to push
Finished pull
Nothing to push
Slow query took 86ms: SELECT entityName, entityId, hash FROM entity_changes WHERE isSynced = 1 AND entityName != 'note_reordering'
Content hash computation took 113ms
Content hash checks PASSED
Sending message to all clients: {"type":"sync-finished","lastSyncedPush":29993}
^C⏎                                                                                                                                                                                                                                                                                                                          matt@fedora ~> 

Screenshot from 2022-01-01 13-34-57

I tried syncing locally from a server instance

sigaloid commented 2 years ago

For issues of syncing I have found my best (and only) option is just sending the document.db directly.

zadam commented 2 years ago

Table counts: notes: 0, note_revisions: 28, branches: 0, attributes: 0, api_tokens: 0

Hi, it looks like there's 0 notes in your document which is quite strange and should not happen.

Do you know how did this happen?

sigaloid commented 2 years ago

I was using the server version in the browser for very long but installed the desktop version finally, I simply set up syncing on the local version by logging in.

On the server, I clicked fill entity changes records, fix consistency issues, and vaccum'd the database before syncing.

sigaloid commented 2 years ago

This is really weird - it seems like when it's done syncing, it starts pushing changes out (despite no local changes being made)

Pulled 1000 changes in 456 KB, starting at entityChangeId=212716 in 313ms and applied them in 2835ms, 498 outstanding pulls
Returning sync stats: {"initialized":false,"outstandingPullCount":498}
200 GET /api/sync/stats with 48 bytes took 0ms
Returning sync stats: {"initialized":false,"outstandingPullCount":498}
304 GET /api/sync/stats with 48 bytes took 1ms
Returning sync stats: {"initialized":false,"outstandingPullCount":498}
304 GET /api/sync/stats with 48 bytes took 1ms
Pulled 498 changes in 224 KB, starting at entityChangeId=213716 in 271ms and applied them in 1505ms, 0 outstanding pulls
Returning sync stats: {"initialized":false,"outstandingPullCount":0}
200 GET /api/sync/stats with 46 bytes took 1ms
Finished pull
Returning sync stats: {"initialized":false,"outstandingPullCount":0}
304 GET /api/sync/stats with 46 bytes took 1ms
Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":0}
***// Begins pushing out changes...***
Pushing 1000 sync changes in 545ms
Returning sync stats: {"initialized":false,"outstandingPullCount":0}
304 GET /api/sync/stats with 46 bytes took 1ms
Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":1014}
Pushing 1000 sync changes in 656ms
Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2014}
Pushing 1000 sync changes in 598ms
Returning sync stats: {"initialized":false,"outstandingPullCount":0}
304 GET /api/sync/stats with 46 bytes took 1ms
Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3014}
Pushing 1000 sync changes in 509ms

I think every time I clear local data and retry syncing, the total changes count increases (I think it's doubled since last time). Like, syncing causes the total sync count to double, as if there's a problem locally causing the changes to be considered "different" so it re-pushes them back out. I've never seen this happen before while syncing though

sigaloid commented 2 years ago

Okay, so the syncing has finished completely except the logs are filled with Screenshot from 2022-01-01 16-16-22

It does indeed sync completely now, though, and the application runs as expected.

zadam commented 2 years ago

Could you please share full desktop client log to zadam.apps@gmail.com?

I'd like to understand how it got to that 0 notes. That doesn't seem right. Thanks.

sigaloid commented 2 years ago

I can't replicate the zero notes, but here's a log from a brand new sync, clean 0.48.3 version, nothing locally:

Details ``` CPU model: AMD Athlon Silver 3050U with Radeon Graphics, logical cores: 2 freq: 3015 Mhz Listening on port 37840 libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null) [32486:0108/124638.020344:ERROR:sandbox_linux.cc(376)] InitializeSandbox() called with multiple threads in process gpu-process. Triggering sync. Returning sync stats: {"initialized":false,"outstandingPullCount":0} 200 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":0} Pushing 1000 sync changes in 1186ms Nothing to push Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-pull-in-progress","lastSyncedPush":1014} Pulled 1000 changes in 551 KB, starting at entityChangeId=205493 in 504ms and applied them in 259ms, 74341 outstanding pulls Pulled 418 changes in 2242 KB, starting at entityChangeId=206503 in 583ms and applied them in 221ms, 73920 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73920} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 20 changes in 3188 KB, starting at entityChangeId=206924 in 493ms and applied them in 92ms, 73900 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73900} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 14 changes in 2580 KB, starting at entityChangeId=206944 in 300ms and applied them in 146ms, 73886 outstanding pulls Pulled 7 changes in 3054 KB, starting at entityChangeId=206958 in 336ms and applied them in 104ms, 73879 outstanding pulls Pulled 18 changes in 2673 KB, starting at entityChangeId=206965 in 276ms and applied them in 84ms, 73860 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73860} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 23 changes in 2571 KB, starting at entityChangeId=206984 in 254ms and applied them in 80ms, 73837 outstanding pulls Pulled 33 changes in 3096 KB, starting at entityChangeId=207007 in 277ms and applied them in 88ms, 73804 outstanding pulls Pulled 14 changes in 2669 KB, starting at entityChangeId=207040 in 205ms and applied them in 157ms, 73790 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73790} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 43 changes in 5214 KB, starting at entityChangeId=207054 in 413ms and applied them in 169ms, 73746 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73746} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 8 changes in 4142 KB, starting at entityChangeId=207098 in 464ms and applied them in 143ms, 73737 outstanding pulls Pulled 7 changes in 3152 KB, starting at entityChangeId=207107 in 298ms and applied them in 81ms, 73730 outstanding pulls Pulled 17 changes in 2501 KB, starting at entityChangeId=207114 in 209ms and applied them in 149ms, 73713 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73713} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 21 changes in 2917 KB, starting at entityChangeId=207131 in 247ms and applied them in 84ms, 73692 outstanding pulls Pulled 21 changes in 2701 KB, starting at entityChangeId=207152 in 221ms and applied them in 73ms, 73669 outstanding pulls Pulled 5 changes in 2534 KB, starting at entityChangeId=207175 in 187ms and applied them in 68ms, 73664 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73664} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 10 changes in 4208 KB, starting at entityChangeId=207180 in 289ms and applied them in 131ms, 73654 outstanding pulls Pulled 26 changes in 4178 KB, starting at entityChangeId=207190 in 306ms and applied them in 185ms, 73627 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73627} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 12 changes in 3784 KB, starting at entityChangeId=207217 in 322ms and applied them in 106ms, 73615 outstanding pulls Pulled 9 changes in 2610 KB, starting at entityChangeId=207229 in 220ms and applied them in 71ms, 73606 outstanding pulls Pulled 45 changes in 3650 KB, starting at entityChangeId=207238 in 250ms and applied them in 110ms, 73560 outstanding pulls Pulled 25 changes in 2549 KB, starting at entityChangeId=207284 in 175ms and applied them in 77ms, 73535 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73535} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 21 changes in 2646 KB, starting at entityChangeId=207309 in 208ms and applied them in 135ms, 73514 outstanding pulls Pulled 18 changes in 3486 KB, starting at entityChangeId=207330 in 182ms and applied them in 115ms, 73496 outstanding pulls Pulled 13 changes in 2929 KB, starting at entityChangeId=207348 in 196ms and applied them in 84ms, 73483 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73483} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 25 changes in 4856 KB, starting at entityChangeId=207361 in 252ms and applied them in 144ms, 73458 outstanding pulls Pulled 23 changes in 3656 KB, starting at entityChangeId=207386 in 221ms and applied them in 175ms, 73434 outstanding pulls Pulled 16 changes in 2584 KB, starting at entityChangeId=207410 in 178ms and applied them in 106ms, 73417 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73417} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 6 changes in 2619 KB, starting at entityChangeId=207427 in 164ms and applied them in 82ms, 73410 outstanding pulls Pulled 13 changes in 4560 KB, starting at entityChangeId=207434 in 278ms and applied them in 138ms, 73396 outstanding pulls Pulled 34 changes in 2600 KB, starting at entityChangeId=207448 in 168ms and applied them in 76ms, 73362 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73362} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 14 changes in 2548 KB, starting at entityChangeId=207482 in 156ms and applied them in 136ms, 73348 outstanding pulls Pulled 22 changes in 2753 KB, starting at entityChangeId=207496 in 198ms and applied them in 121ms, 73326 outstanding pulls Pulled 3 changes in 3747 KB, starting at entityChangeId=207518 in 202ms and applied them in 138ms, 73323 outstanding pulls 200 GET /api/clipper/handshake with 45 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":73323} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 27 changes in 2565 KB, starting at entityChangeId=207521 in 236ms and applied them in 94ms, 73296 outstanding pulls Pulled 23 changes in 3077 KB, starting at entityChangeId=207548 in 183ms and applied them in 85ms, 73273 outstanding pulls Pulled 11 changes in 2701 KB, starting at entityChangeId=207571 in 180ms and applied them in 146ms, 73262 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73262} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 20 changes in 2878 KB, starting at entityChangeId=207582 in 154ms and applied them in 83ms, 73242 outstanding pulls Pulled 1 changes in 3427 KB, starting at entityChangeId=207602 in 208ms and applied them in 97ms, 73241 outstanding pulls Pulled 20 changes in 3216 KB, starting at entityChangeId=207603 in 181ms and applied them in 102ms, 73221 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73221} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 22 changes in 2991 KB, starting at entityChangeId=207623 in 471ms and applied them in 112ms, 73199 outstanding pulls Pulled 37 changes in 2630 KB, starting at entityChangeId=207645 in 212ms and applied them in 182ms, 73161 outstanding pulls Pulled 18 changes in 4519 KB, starting at entityChangeId=207683 in 243ms and applied them in 148ms, 73143 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73143} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 18 changes in 2996 KB, starting at entityChangeId=207701 in 162ms and applied them in 124ms, 73125 outstanding pulls Pulled 17 changes in 4590 KB, starting at entityChangeId=207719 in 246ms and applied them in 138ms, 73108 outstanding pulls Pulled 24 changes in 2800 KB, starting at entityChangeId=207736 in 196ms and applied them in 437ms, 73084 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73084} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 23 changes in 2598 KB, starting at entityChangeId=207760 in 206ms and applied them in 104ms, 73061 outstanding pulls Pulled 33 changes in 2990 KB, starting at entityChangeId=207783 in 209ms and applied them in 112ms, 73028 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":73028} 200 GET /api/sync/stats with 50 bytes took 6ms Pulled 16 changes in 2662 KB, starting at entityChangeId=207816 in 240ms and applied them in 99ms, 73012 outstanding pulls Pulled 19 changes in 3894 KB, starting at entityChangeId=207832 in 245ms and applied them in 161ms, 72993 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72993} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 24 changes in 5294 KB, starting at entityChangeId=207851 in 330ms and applied them in 216ms, 72969 outstanding pulls Pulled 16 changes in 4718 KB, starting at entityChangeId=207875 in 248ms and applied them in 139ms, 72953 outstanding pulls Pulled 17 changes in 3200 KB, starting at entityChangeId=207891 in 183ms and applied them in 93ms, 72936 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72936} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 12 changes in 2776 KB, starting at entityChangeId=207908 in 165ms and applied them in 99ms, 72924 outstanding pulls Pulled 14 changes in 3321 KB, starting at entityChangeId=207920 in 181ms and applied them in 171ms, 72910 outstanding pulls Pulled 15 changes in 3161 KB, starting at entityChangeId=207934 in 232ms and applied them in 103ms, 72895 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72895} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 12 changes in 4330 KB, starting at entityChangeId=207949 in 215ms and applied them in 157ms, 72883 outstanding pulls Pulled 10 changes in 2658 KB, starting at entityChangeId=207961 in 172ms and applied them in 91ms, 72873 outstanding pulls Pulled 7 changes in 5395 KB, starting at entityChangeId=207971 in 303ms and applied them in 300ms, 72866 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72866} 200 GET /api/sync/stats with 50 bytes took 3ms Pulled 24 changes in 2855 KB, starting at entityChangeId=207978 in 185ms and applied them in 129ms, 72842 outstanding pulls Pulled 15 changes in 2657 KB, starting at entityChangeId=208002 in 148ms and applied them in 147ms, 72827 outstanding pulls Pulled 19 changes in 3853 KB, starting at entityChangeId=208017 in 206ms and applied them in 185ms, 72808 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72808} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 17 changes in 2588 KB, starting at entityChangeId=208036 in 160ms and applied them in 80ms, 72791 outstanding pulls Pulled 11 changes in 6460 KB, starting at entityChangeId=208053 in 360ms and applied them in 246ms, 72780 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72780} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 17 changes in 8011 KB, starting at entityChangeId=208064 in 356ms and applied them in 243ms, 72763 outstanding pulls Pulled 25 changes in 2653 KB, starting at entityChangeId=208081 in 155ms and applied them in 86ms, 72737 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72737} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 4 changes in 3912 KB, starting at entityChangeId=208107 in 209ms and applied them in 189ms, 72733 outstanding pulls Pulled 30 changes in 2758 KB, starting at entityChangeId=208111 in 173ms and applied them in 111ms, 72702 outstanding pulls Pulled 26 changes in 5536 KB, starting at entityChangeId=208142 in 397ms and applied them in 160ms, 72676 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72676} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 16 changes in 2896 KB, starting at entityChangeId=208168 in 204ms and applied them in 112ms, 72660 outstanding pulls Pulled 24 changes in 5174 KB, starting at entityChangeId=208184 in 279ms and applied them in 233ms, 72636 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72636} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 23 changes in 3428 KB, starting at entityChangeId=208208 in 199ms and applied them in 100ms, 72613 outstanding pulls Pulled 4 changes in 4469 KB, starting at entityChangeId=208231 in 252ms and applied them in 118ms, 72609 outstanding pulls Pulled 31 changes in 3455 KB, starting at entityChangeId=208235 in 193ms and applied them in 125ms, 72578 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72578} 200 GET /api/sync/stats with 50 bytes took 4ms Pulled 4 changes in 4148 KB, starting at entityChangeId=208266 in 221ms and applied them in 183ms, 72574 outstanding pulls Pulled 17 changes in 4221 KB, starting at entityChangeId=208270 in 250ms and applied them in 137ms, 72557 outstanding pulls Pulled 16 changes in 3010 KB, starting at entityChangeId=208287 in 190ms and applied them in 84ms, 72540 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72540} 200 GET /api/sync/stats with 50 bytes took 2ms Pulled 19 changes in 4431 KB, starting at entityChangeId=208304 in 225ms and applied them in 129ms, 72521 outstanding pulls Pulled 22 changes in 3426 KB, starting at entityChangeId=208323 in 219ms and applied them in 167ms, 72499 outstanding pulls Pulled 6 changes in 2973 KB, starting at entityChangeId=208345 in 184ms and applied them in 80ms, 72493 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72493} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 17 changes in 4242 KB, starting at entityChangeId=208351 in 245ms and applied them in 121ms, 72476 outstanding pulls Pulled 18 changes in 3070 KB, starting at entityChangeId=208368 in 176ms and applied them in 104ms, 72458 outstanding pulls Pulled 13 changes in 5342 KB, starting at entityChangeId=208386 in 282ms and applied them in 189ms, 72445 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72445} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1 changes in 2482 KB, starting at entityChangeId=208399 in 171ms and applied them in 74ms, 72444 outstanding pulls Pulled 16 changes in 2560 KB, starting at entityChangeId=208400 in 155ms and applied them in 76ms, 72428 outstanding pulls Pulled 17 changes in 2949 KB, starting at entityChangeId=208416 in 182ms and applied them in 80ms, 72411 outstanding pulls Pulled 37 changes in 2641 KB, starting at entityChangeId=208433 in 170ms and applied them in 80ms, 72373 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72373} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 13 changes in 3825 KB, starting at entityChangeId=208471 in 219ms and applied them in 162ms, 72360 outstanding pulls Pulled 10 changes in 3057 KB, starting at entityChangeId=208484 in 183ms and applied them in 85ms, 72350 outstanding pulls Pulled 18 changes in 2886 KB, starting at entityChangeId=208494 in 185ms and applied them in 78ms, 72332 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72332} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 23 changes in 4131 KB, starting at entityChangeId=208512 in 243ms and applied them in 117ms, 72309 outstanding pulls Pulled 7 changes in 2922 KB, starting at entityChangeId=208535 in 168ms and applied them in 86ms, 72302 outstanding pulls Pulled 11 changes in 3875 KB, starting at entityChangeId=208542 in 247ms and applied them in 183ms, 72291 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72291} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 3 changes in 3599 KB, starting at entityChangeId=208553 in 200ms and applied them in 104ms, 72288 outstanding pulls Pulled 14 changes in 3401 KB, starting at entityChangeId=208556 in 197ms and applied them in 105ms, 72274 outstanding pulls Pulled 15 changes in 2655 KB, starting at entityChangeId=208570 in 183ms and applied them in 74ms, 72259 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72259} 200 GET /api/sync/stats with 50 bytes took 3ms Pulled 6 changes in 2736 KB, starting at entityChangeId=208585 in 165ms and applied them in 76ms, 72253 outstanding pulls Pulled 14 changes in 3283 KB, starting at entityChangeId=208591 in 180ms and applied them in 161ms, 72239 outstanding pulls Pulled 13 changes in 2540 KB, starting at entityChangeId=208605 in 211ms and applied them in 93ms, 72226 outstanding pulls Pulled 12 changes in 3785 KB, starting at entityChangeId=208618 in 196ms and applied them in 103ms, 72214 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72214} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 15 changes in 5296 KB, starting at entityChangeId=208630 in 242ms and applied them in 148ms, 72199 outstanding pulls Pulled 27 changes in 2683 KB, starting at entityChangeId=208645 in 176ms and applied them in 143ms, 72172 outstanding pulls Pulled 5 changes in 4319 KB, starting at entityChangeId=208672 in 217ms and applied them in 144ms, 72167 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72167} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 20 changes in 2551 KB, starting at entityChangeId=208677 in 144ms and applied them in 76ms, 72147 outstanding pulls Pulled 10 changes in 5092 KB, starting at entityChangeId=208697 in 229ms and applied them in 139ms, 72137 outstanding pulls Pulled 9 changes in 2608 KB, starting at entityChangeId=208707 in 163ms and applied them in 144ms, 72128 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":72128} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 1445 KB, starting at entityChangeId=208716 in 176ms and applied them in 443ms, 71113 outstanding pulls Pulled 1000 changes in 430 KB, starting at entityChangeId=209731 in 148ms and applied them in 539ms, 70091 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":70091} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 456 KB, starting at entityChangeId=210753 in 226ms and applied them in 649ms, 69089 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":69089} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 456 KB, starting at entityChangeId=211755 in 228ms and applied them in 771ms, 68085 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":68085} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 456 KB, starting at entityChangeId=212759 in 189ms and applied them in 804ms, 67082 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":67082} 200 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 323 KB, starting at entityChangeId=213762 in 150ms and applied them in 855ms, 36609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":36609} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 223 KB, starting at entityChangeId=244235 in 128ms and applied them in 946ms, 35609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":35609} 200 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 224 KB, starting at entityChangeId=245235 in 166ms and applied them in 979ms, 34609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":34609} 200 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 224 KB, starting at entityChangeId=246235 in 174ms and applied them in 1406ms, 33609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":33609} Slow 200 GET /api/sync/stats with 50 bytes took 25ms Returning sync stats: {"initialized":false,"outstandingPullCount":33609} Slow 304 GET /api/sync/stats with 50 bytes took 15ms Pulled 1000 changes in 224 KB, starting at entityChangeId=247235 in 233ms and applied them in 1212ms, 32609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":32609} 200 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 223 KB, starting at entityChangeId=248235 in 185ms and applied them in 1343ms, 31609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":31609} 200 GET /api/sync/stats with 50 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":31609} 304 GET /api/sync/stats with 50 bytes took 2ms Pulled 1000 changes in 235 KB, starting at entityChangeId=249235 in 183ms and applied them in 1349ms, 30609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":30609} 200 GET /api/sync/stats with 50 bytes took 3ms Pulled 1000 changes in 223 KB, starting at entityChangeId=250235 in 255ms and applied them in 1553ms, 29609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":29609} 200 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":29609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 214 KB, starting at entityChangeId=251235 in 191ms and applied them in 1611ms, 28609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":28609} 200 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":28609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 214 KB, starting at entityChangeId=252235 in 186ms and applied them in 1723ms, 27609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":27609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":27609} 304 GET /api/sync/stats with 50 bytes took 4ms Pulled 1000 changes in 219 KB, starting at entityChangeId=253235 in 186ms and applied them in 1847ms, 26609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":26609} 200 GET /api/sync/stats with 50 bytes took 3ms Returning sync stats: {"initialized":false,"outstandingPullCount":26609} 304 GET /api/sync/stats with 50 bytes took 3ms Pulled 1000 changes in 223 KB, starting at entityChangeId=254235 in 192ms and applied them in 2278ms, 25609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":25609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":25609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 222 KB, starting at entityChangeId=255235 in 183ms and applied them in 1828ms, 24609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":24609} 200 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":24609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 217 KB, starting at entityChangeId=256235 in 192ms and applied them in 2003ms, 23609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":23609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":23609} 304 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":23609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 217 KB, starting at entityChangeId=257235 in 376ms and applied them in 2065ms, 22609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":22609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":22609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 217 KB, starting at entityChangeId=258235 in 192ms and applied them in 2120ms, 21609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":21609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":21609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=259235 in 205ms and applied them in 2230ms, 20609 outstanding pulls 304 GET /api/clipper/handshake with 45 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":20609} 200 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":20609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":20609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=260235 in 204ms and applied them in 2470ms, 19609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":19609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":19609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 220 KB, starting at entityChangeId=261235 in 274ms and applied them in 2567ms, 18609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":18609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":18609} 304 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":18609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":18609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=262235 in 576ms and applied them in 2554ms, 17609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":17609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":17609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":17609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=263235 in 416ms and applied them in 2590ms, 16609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":16609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":16609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 220 KB, starting at entityChangeId=264235 in 196ms and applied them in 2866ms, 15609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":15609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":15609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":15609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":15609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=265235 in 390ms and applied them in 2805ms, 14609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":14609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":14609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":14609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=266235 in 193ms and applied them in 2920ms, 13609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":13609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":13609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":13609} 304 GET /api/sync/stats with 50 bytes took 2ms Pulled 1000 changes in 219 KB, starting at entityChangeId=267235 in 530ms and applied them in 3081ms, 12609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":12609} 200 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":12609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":12609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=268235 in 402ms and applied them in 3356ms, 11609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":11609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":11609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":11609} 304 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":11609} 304 GET /api/sync/stats with 50 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=269235 in 196ms and applied them in 3443ms, 10609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":10609} 200 GET /api/sync/stats with 50 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":10609} 304 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":10609} 304 GET /api/sync/stats with 50 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":10609} 304 GET /api/sync/stats with 50 bytes took 0ms Pulled 1000 changes in 220 KB, starting at entityChangeId=270235 in 478ms and applied them in 3348ms, 9609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":9609} 200 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":9609} 304 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":9609} 304 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":9609} 304 GET /api/sync/stats with 49 bytes took 1ms Pulled 1000 changes in 220 KB, starting at entityChangeId=271235 in 543ms and applied them in 3460ms, 8609 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":8609} 200 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":8609} 304 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":8609} 304 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":8609} 304 GET /api/sync/stats with 49 bytes took 1ms Pulled 1000 changes in 896 KB, starting at entityChangeId=272235 in 644ms and applied them in 3875ms, 7471 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":7471} 200 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":7471} 304 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":7471} 304 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":7471} 304 GET /api/sync/stats with 49 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":7471} 304 GET /api/sync/stats with 49 bytes took 1ms Pulled 157 changes in 9981 KB, starting at entityChangeId=273373 in 1276ms and applied them in 1082ms, 7230 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":7230} 200 GET /api/sync/stats with 49 bytes took 3ms Pulled 5 changes in 3575 KB, starting at entityChangeId=273614 in 260ms and applied them in 110ms, 7225 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":7225} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 16 changes in 3426 KB, starting at entityChangeId=273619 in 194ms and applied them in 158ms, 7209 outstanding pulls Pulled 345 changes in 10704 KB, starting at entityChangeId=273635 in 593ms and applied them in 1817ms, 6694 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":6694} 200 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":6694} 304 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":6694} 304 GET /api/sync/stats with 49 bytes took 0ms Pulled 5 changes in 3575 KB, starting at entityChangeId=274150 in 263ms and applied them in 109ms, 6689 outstanding pulls Pulled 16 changes in 3426 KB, starting at entityChangeId=274155 in 191ms and applied them in 145ms, 6673 outstanding pulls Pulled 341 changes in 2313 KB, starting at entityChangeId=274171 in 182ms and applied them in 1436ms, 6043 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":6043} 200 GET /api/sync/stats with 49 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":6043} 304 GET /api/sync/stats with 49 bytes took 1ms Pulled 101 changes in 5230 KB, starting at entityChangeId=274801 in 358ms and applied them in 532ms, 5776 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":5776} 200 GET /api/sync/stats with 49 bytes took 0ms Pulled 2 changes in 3178 KB, starting at entityChangeId=275068 in 170ms and applied them in 87ms, 5774 outstanding pulls Pulled 52 changes in 3091 KB, starting at entityChangeId=275070 in 173ms and applied them in 355ms, 5716 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":5716} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 12 changes in 3052 KB, starting at entityChangeId=275128 in 217ms and applied them in 126ms, 5704 outstanding pulls Pulled 151 changes in 2557 KB, starting at entityChangeId=275140 in 166ms and applied them in 696ms, 3750 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":3750} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 31 changes in 3888 KB, starting at entityChangeId=277094 in 209ms and applied them in 320ms, 3553 outstanding pulls Pulled 2 changes in 2704 KB, starting at entityChangeId=277291 in 177ms and applied them in 86ms, 3549 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":3549} 200 GET /api/sync/stats with 49 bytes took 4ms Pulled 2 changes in 8735 KB, starting at entityChangeId=277295 in 382ms and applied them in 274ms, 3545 outstanding pulls Pulled 2 changes in 4739 KB, starting at entityChangeId=277299 in 228ms and applied them in 195ms, 3541 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":3541} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 18 changes in 2807 KB, starting at entityChangeId=277303 in 158ms and applied them in 154ms, 3505 outstanding pulls Pulled 238 changes in 3895 KB, starting at entityChangeId=277339 in 210ms and applied them in 1169ms, 3214 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":3214} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 4 changes in 2705 KB, starting at entityChangeId=277630 in 200ms and applied them in 144ms, 3210 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":3210} 200 GET /api/sync/stats with 49 bytes took 2ms Pulled 4 changes in 8736 KB, starting at entityChangeId=277634 in 391ms and applied them in 265ms, 3206 outstanding pulls Pulled 4 changes in 4740 KB, starting at entityChangeId=277638 in 222ms and applied them in 222ms, 3202 outstanding pulls 304 GET /api/clipper/handshake with 45 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":3202} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 36 changes in 2818 KB, starting at entityChangeId=277642 in 169ms and applied them in 219ms, 3166 outstanding pulls Pulled 232 changes in 2540 KB, starting at entityChangeId=277678 in 150ms and applied them in 1054ms, 1390 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":1390} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 38 changes in 4941 KB, starting at entityChangeId=279454 in 271ms and applied them in 387ms, 1342 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":1342} 200 GET /api/sync/stats with 49 bytes took 1ms Pulled 3 changes in 3669 KB, starting at entityChangeId=279502 in 166ms and applied them in 153ms, 1337 outstanding pulls Pulled 35 changes in 4858 KB, starting at entityChangeId=279507 in 289ms and applied them in 278ms, 752 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":752} 200 GET /api/sync/stats with 48 bytes took 1ms Pulled 151 changes in 1839 KB, starting at entityChangeId=280092 in 114ms and applied them in 759ms, 0 outstanding pulls Returning sync stats: {"initialized":false,"outstandingPullCount":0} 200 GET /api/sync/stats with 46 bytes took 1ms Finished pull Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":1014} Pushing 1000 sync changes in 530ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2014} Pushing 418 sync changes in 1305ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2432} Pushing 20 sync changes in 1310ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2452} Pushing 14 sync changes in 1345ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2466} Pushing 7 sync changes in 1465ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2473} Pushing 18 sync changes in 1313ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2491} Pushing 23 sync changes in 1346ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2514} Pushing 33 sync changes in 1588ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2547} Pushing 14 sync changes in 1281ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2561} Pushing 43 sync changes in 2138ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2604} Pushing 8 sync changes in 1673ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2612} Pushing 7 sync changes in 1092ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2619} Pushing 17 sync changes in 1276ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2636} Pushing 21 sync changes in 1362ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2657} Pushing 21 sync changes in 1242ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2678} Pushing 5 sync changes in 796ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2683} Pushing 10 sync changes in 1803ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2693} Pushing 26 sync changes in 1794ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 3ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2719} Pushing 12 sync changes in 1810ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 3ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2731} Pushing 9 sync changes in 1311ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2740} Pushing 45 sync changes in 1738ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2785} Pushing 25 sync changes in 1109ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2810} Pushing 21 sync changes in 1240ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2831} Pushing 18 sync changes in 1413ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2849} Pushing 13 sync changes in 1385ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms ^ASending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2862} Pushing 25 sync changes in 2233ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2887} Pushing 23 sync changes in 1702ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2910} Pushing 16 sync changes in 1086ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2926} Pushing 6 sync changes in 902ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2932} Pushing 13 sync changes in 2086ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2945} Pushing 34 sync changes in 1193ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2979} Pushing 14 sync changes in 1220ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":2993} Pushing 22 sync changes in 1053ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3015} Pushing 3 sync changes in 1885ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3018} Pushing 27 sync changes in 920ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3045} Pushing 23 sync changes in 1522ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3068} Pushing 11 sync changes in 1315ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3079} Pushing 20 sync changes in 1360ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3099} Pushing 1 sync changes in 1255ms 304 GET /api/clipper/handshake with 45 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3100} Pushing 20 sync changes in 1607ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3120} Pushing 22 sync changes in 1368ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3142} Pushing 37 sync changes in 1112ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3179} Pushing 18 sync changes in 1527ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3197} Pushing 18 sync changes in 1525ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3215} Pushing 17 sync changes in 1866ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3232} Pushing 24 sync changes in 1445ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3256} Pushing 23 sync changes in 911ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3279} Pushing 33 sync changes in 1179ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3312} Pushing 16 sync changes in 1028ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3328} Pushing 19 sync changes in 1896ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3347} Pushing 24 sync changes in 2302ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 2ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3371} Pushing 16 sync changes in 2303ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3387} Pushing 17 sync changes in 1717ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3404} Pushing 12 sync changes in 1286ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3416} Pushing 14 sync changes in 1615ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3430} Pushing 15 sync changes in 1124ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3445} Pushing 12 sync changes in 2164ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 0ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3457} Pushing 10 sync changes in 1339ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms Sending message to all clients: {"type":"sync-push-in-progress","lastSyncedPush":3467} Pushing 7 sync changes in 2409ms Returning sync stats: {"initialized":false,"outstandingPullCount":0} 304 GET /api/sync/stats with 46 bytes took 1ms [matt@fedora ~]$ ./Downloads/trilium-linux-x64-0.49.3/trilium-linux-x64/trilium--^C [matt@fedora ~]$ ```

It started pushing changes out for some reason, I cancelled it in the middle of it. I'm going to restart the docker container in a blank folder and start from scratch.

Manually moving the .db file didn't fix it either :upside_down_face: I must be doing something wrong with my sync setup

zadam commented 2 years ago

Hi, this is actually expected. The client pulls the changes, but when it comes to pushing, it sees the new changes in the database but doesn't remember they actually come from the same server, so it sends them back to their source. Server will then ignore them since they were already applied before.

So this is an inefficiency issue where each change will be sent needlessly twice. It is certainly fixable, but the sync protocol is quite tricky and so far I was putting more emphasis on making sure the sync will end correctly.

But it should be addressed at some point.

sigaloid commented 2 years ago

Ah. I saw the server document.db doubling in size at some point when it was doing that and I assumed that if it starts doing that, it means it got confused and starts saving each change separately (and this was happening every new device I added, so I was thinking it would exponentially increase for every new device). I just reset and reimported serverside and clientside, and it did indeed do the same thing. Apologies! At least now I did some well-needed cleaning out of my database :p thank you so much for the help!