Client sync to server does not complete

[reefland]

Trilium Version

0.49.3

What operating system are you using?

Other Linux

What is your setup?

Local + server sync

Operating System Version

Linux dldsk01 5.14.21-2-MANJARO #1 SMP PREEMPT Sun Nov 21 22:43:47 UTC 2021 x86_64 GNU/Linux

Description

Working server instance on docker running zadam/trilium:latest version: 0.49.5

I installed Trilium Notes via Arch AUR on my desktop & laptop. Both running Manjaro Arch both using 0.49.3 - Laptop is fine, installed and synced to server no issues.

On my desktop, at the Welcome Screen:
Select "Sync from Server"

• Enter my server URL
• Enter my Username and Password
• Click [ Finish setup]

It stays at "Sync in progress" and nothing happens. The following is the log on the desktop client:

$ tail -f ~/.local/share/trilium-data/log/trilium-2022-01-17.log 
  "appVersion": "0.49.3",
  "dbVersion": 189,
  "syncVersion": 23,
  "buildDate": "2022-01-06T23:09:17+01:00",
  "buildRevision": "590eea11830531699643b381d06a6a59dd7704bb",
  "dataDirectory": "/home/rich/.local/share/trilium-data",
  "clipperProtocolVersion": "1.0"
}
11:39:43.042 CPU model: AMD Ryzen 7 3700X 8-Core Processor, logical cores: 16 freq: 3600 Mhz
11:39:43.044 Listening on port 37840
11:40:36.279 Getting document options FROM sync server.
11:40:36.393 Creating database for sync
11:40:36.397 Schema and not synced options generated.
11:40:36.397 Triggering sync.
11:40:36.398 Slow 200 POST /api/setup/sync-from-server with 20 bytes took 119ms
11:40:36.445 Nothing to push
11:40:36.548 Pulled 504 changes in 1001 KB, starting at entityChangeId=0 in 98ms and applied them in 5ms, 30751 outstanding pulls
11:40:36.628 Pulled 645 changes in 978 KB, starting at entityChangeId=563 in 75ms and applied them in 5ms, 30025 outstanding pulls
11:40:36.710 Pulled 648 changes in 1064 KB, starting at entityChangeId=1289 in 75ms and applied them in 7ms, 29285 outstanding pulls
11:40:36.821 Pulled 957 changes in 978 KB, starting at entityChangeId=2029 in 106ms and applied them in 5ms, 28303 outstanding pulls
11:40:36.912 Pulled 328 changes in 979 KB, starting at entityChangeId=3011 in 87ms and applied them in 4ms, 27975 outstanding pulls
11:40:36.991 Pulled 138 changes in 1033 KB, starting at entityChangeId=3339 in 75ms and applied them in 4ms, 27837 outstanding pulls
11:40:37.078 Pulled 930 changes in 978 KB, starting at entityChangeId=3477 in 82ms and applied them in 5ms, 26883 outstanding pulls
11:40:37.163 Pulled 559 changes in 982 KB, starting at entityChangeId=4431 in 79ms and applied them in 6ms, 26308 outstanding pulls
11:40:37.247 Pulled 795 changes in 978 KB, starting at entityChangeId=5006 in 80ms and applied them in 4ms, 25483 outstanding pulls
11:40:37.326 Pulled 775 changes in 978 KB, starting at entityChangeId=5831 in 76ms and applied them in 3ms, 24688 outstanding pulls
11:40:37.400 Pulled 294 changes in 1065 KB, starting at entityChangeId=6626 in 72ms and applied them in 2ms, 24392 outstanding pulls
11:40:37.405 Returning sync stats: {"initialized":false,"outstandingPullCount":24392}
11:40:37.405 200 GET /api/sync/stats with 50 bytes took 0ms
11:40:37.491 Pulled 771 changes in 1040 KB, starting at entityChangeId=6922 in 86ms and applied them in 5ms, 23599 outstanding pulls
11:40:37.572 Pulled 637 changes in 983 KB, starting at entityChangeId=7715 in 76ms and applied them in 5ms, 22955 outstanding pulls
11:40:37.651 Pulled 716 changes in 980 KB, starting at entityChangeId=8359 in 74ms and applied them in 5ms, 22215 outstanding pulls
11:40:37.730 Pulled 626 changes in 977 KB, starting at entityChangeId=9099 in 74ms and applied them in 5ms, 21559 outstanding pulls
11:40:37.812 Pulled 750 changes in 978 KB, starting at entityChangeId=9755 in 77ms and applied them in 5ms, 20625 outstanding pulls
11:40:37.893 Pulled 844 changes in 991 KB, starting at entityChangeId=10689 in 76ms and applied them in 5ms, 19745 outstanding pulls
11:40:37.973 Pulled 117 changes in 985 KB, starting at entityChangeId=11569 in 75ms and applied them in 5ms, 19627 outstanding pulls
11:40:38.051 Pulled 131 changes in 1000 KB, starting at entityChangeId=11687 in 73ms and applied them in 5ms, 19492 outstanding pulls
11:40:38.127 Pulled 475 changes in 993 KB, starting at entityChangeId=11822 in 70ms and applied them in 6ms, 19003 outstanding pulls
11:40:38.212 Pulled 321 changes in 977 KB, starting at entityChangeId=12311 in 79ms and applied them in 6ms, 18526 outstanding pulls
11:40:38.281 Pulled 238 changes in 983 KB, starting at entityChangeId=12788 in 63ms and applied them in 6ms, 18275 outstanding pulls
11:40:38.361 Pulled 244 changes in 996 KB, starting at entityChangeId=13039 in 74ms and applied them in 6ms, 18008 outstanding pulls
11:40:38.404 Returning sync stats: {"initialized":false,"outstandingPullCount":18008}
11:40:38.404 200 GET /api/sync/stats with 50 bytes took 0ms
11:40:38.443 Pulled 697 changes in 1003 KB, starting at entityChangeId=13306 in 77ms and applied them in 5ms, 17233 outstanding pulls
11:40:38.542 Pulled 675 changes in 983 KB, starting at entityChangeId=14081 in 94ms and applied them in 5ms, 16246 outstanding pulls
11:40:38.625 Pulled 649 changes in 977 KB, starting at entityChangeId=15068 in 78ms and applied them in 5ms, 15371 outstanding pulls
11:40:38.716 Pulled 431 changes in 984 KB, starting at entityChangeId=15943 in 84ms and applied them in 7ms, 14905 outstanding pulls
11:40:38.788 Pulled 184 changes in 977 KB, starting at entityChangeId=16409 in 68ms and applied them in 3ms, 14720 outstanding pulls
11:40:38.868 Pulled 653 changes in 978 KB, starting at entityChangeId=16594 in 76ms and applied them in 4ms, 14045 outstanding pulls
11:40:38.945 Pulled 353 changes in 1011 KB, starting at entityChangeId=17269 in 74ms and applied them in 3ms, 13680 outstanding pulls
11:40:39.012 Pulled 234 changes in 977 KB, starting at entityChangeId=17634 in 61ms and applied them in 6ms, 13412 outstanding pulls
11:40:39.091 Pulled 247 changes in 982 KB, starting at entityChangeId=17902 in 74ms and applied them in 5ms, 13157 outstanding pulls
11:40:39.170 Pulled 414 changes in 987 KB, starting at entityChangeId=18157 in 71ms and applied them in 7ms, 12689 outstanding pulls
11:40:39.253 Pulled 203 changes in 1000 KB, starting at entityChangeId=18625 in 77ms and applied them in 6ms, 12476 outstanding pulls
11:40:39.336 Pulled 556 changes in 977 KB, starting at entityChangeId=18838 in 77ms and applied them in 6ms, 11889 outstanding pulls
11:40:39.408 Pulled 246 changes in 986 KB, starting at entityChangeId=19425 in 66ms and applied them in 6ms, 11639 outstanding pulls
11:40:39.411 Returning sync stats: {"initialized":false,"outstandingPullCount":11639}
11:40:39.411 200 GET /api/sync/stats with 50 bytes took 0ms
11:40:39.487 Pulled 329 changes in 984 KB, starting at entityChangeId=19675 in 74ms and applied them in 5ms, 11289 outstanding pulls
11:40:39.815 Pulled 162 changes in 9216 KB, starting at entityChangeId=20025 in 299ms and applied them in 29ms, 11115 outstanding pulls
11:40:39.895 Pulled 326 changes in 977 KB, starting at entityChangeId=20199 in 75ms and applied them in 5ms, 10750 outstanding pulls
11:40:39.968 Pulled 2 changes in 1124 KB, starting at entityChangeId=20564 in 66ms and applied them in 7ms, 10748 outstanding pulls
11:40:40.039 Sending message to all clients: {"type":"sync-pull-in-progress","lastSyncedPush":0}
11:40:40.093 Pulled 1000 changes in 772 KB, starting at entityChangeId=20566 in 71ms and applied them in 54ms, 9644 outstanding pulls
11:40:40.302 Pulled 891 changes in 2460 KB, starting at entityChangeId=21670 in 81ms and applied them in 128ms, 3331 outstanding pulls
11:40:40.407 Pulled 361 changes in 1109 KB, starting at entityChangeId=27983 in 51ms and applied them in 53ms, 0 outstanding pulls
11:40:40.410 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:40.410 200 GET /api/sync/stats with 46 bytes took 0ms
11:40:40.442 Finished pull
11:40:41.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:41.404 304 GET /api/sync/stats with 46 bytes took 0ms
11:40:42.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:42.404 304 GET /api/sync/stats with 46 bytes took 0ms
11:40:43.403 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:43.404 304 GET /api/sync/stats with 46 bytes took 1ms
11:40:44.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:44.404 304 GET /api/sync/stats with 46 bytes took 1ms
11:40:45.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:45.404 304 GET /api/sync/stats with 46 bytes took 0ms
11:40:46.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:46.404 304 GET /api/sync/stats with 46 bytes took 1ms
11:40:47.404 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:47.404 304 GET /api/sync/stats with 46 bytes took 0ms
11:40:48.403 Returning sync stats: {"initialized":false,"outstandingPullCount":0}
11:40:48.404 304 GET /api/sync/stats with 46 bytes took 1ms

And this just goes on and on with the sync stats message.

On the docker console log, I did notice the following:

Slow 304 GET /api/sync/changed?lastEntityChangeId=20564 with 1151332 bytes took 33ms
Returning 1000 entity changes in 31ms
Slow 304 GET /api/sync/changed?lastEntityChangeId=20566 with 790234 bytes took 37ms
Returning 891 entity changes in 27ms
Slow 304 GET /api/sync/changed?lastEntityChangeId=21670 with 1135899 bytes took 39ms
Returning 361 entity changes in 19ms
Slow 304 GET /api/sync/changed?lastEntityChangeId=27983 with 508153 bytes took 24ms
304 GET /api/sync/changed?lastEntityChangeId=31314 with 46 bytes took 4ms
BadRequestError: request aborted
     at IncomingMessage.onAborted (/usr/src/app/node_modules/raw-body/index.js:231:10)
     at IncomingMessage.emit (node:events:390:28)
     at IncomingMessage._destroy (node:_http_incoming:179:10)
     at _destroy (node:internal/streams/destroy:102:25)
     at IncomingMessage.destroy (node:internal/streams/destroy:64:5)
     at abortIncoming (node:_http_server:596:9)
     at socketOnClose (node:_http_server:590:3)
     at Socket.emit (node:events:402:35)
     at TCP.<anonymous> (node:net:687:12)
     at TCP.callbackTrampoline (node:internal/async_hooks:130:17) {
        code: 'ECONNABORTED',
        expected: 220591,
        length: 220591,
        received: 49125,
        type: 'request.aborted'
        }  

I've uninstalled and reinstalled the client multiple times, doing:
rm -r ~/.local/share/trilium-data/ before each attempt.

Keep getting the same issue over and over.

Q: Can I just copy the document.db from the server or laptop to get around this and then try to sync?

[zadam]

Hi, this looks like some kind of low level network error. Something cutting/rejecting the request. I haven't seen this yet ...

Can I just copy the document.db from the server or laptop to get around this and then try to sync?

Yes, you can do that. After you start the server, deactivate the sync settings in Options, otherwise the server will attempt to sync with itself (which it won't do, but the corresponding errors will be filling log files).

[reefland]

I have my server configured to NOT sync with anything. But both the Desktop and Laptop are set to sync to server.

I copied my documents.db from the laptop to my desktop and sync issues went away. No idea what network issues would be present that stops a fresh sync from working but incremental syncs work fine. I'll close this issue.

[reefland]

Ugh, it's back... I can use the server version from the same machine, works fine.

If I try the server status page from a linux prompt, works fine and returns very fast.

$ time curl https://hpmediasrv.rich-durso.us/trilium-main/api/setup/status
{"isInitialized":true,"schemaExists":true,"syncVersion":23}

real    0m0.042s
user    0m0.003s
sys     0m0.008s

If I try a test Sync within Trilium it's slow....

21:03:58.672 Slow 200 POST /api/sync/test with 94 bytes took 10065ms

Updated to 0.49.5 no difference. Any way to enable more verbose logging on the sync process?

11:00:40.780 DB size: 43847 KB
11:00:41.413 Becca (note cache) load took 53ms
11:00:41.457 App HTTP server starting up at port 37840
11:00:41.458 {
  "appVersion": "0.49.5",
  "dbVersion": 189,
  "syncVersion": 23,
  "buildDate": "2022-01-14T21:40:37+01:00",
  "buildRevision": "77c6c4617b634226e12ead172482fe1fe92bc360",
  "dataDirectory": "/home/rich/.local/share/trilium-data",
  "clipperProtocolVersion": "1.0"
}
11:00:41.473 CPU model: AMD Ryzen 7 3700X 8-Core Processor, logical cores: 16 freq: 3600 Mhz
11:00:41.477 Listening on port 37840
11:00:41.528 Keyboard action showNoteInfo found in database, but not in action definition.
11:00:41.528 Keyboard action showLinkMap found in database, but not in action definition.
11:00:41.528 Keyboard action focusOnAttributes found in database, but not in action definition.
11:00:41.528 Keyboard action toggleZenMode found in database, but not in action definition.
11:00:41.534 Registered global shortcut Ctrl+Alt+P for action createNoteIntoInbox
11:00:41.559 Generated CSRF token JWVmiW0q-GHheyeoLaq8yAs9h4Tj_S25ocDM with secret _csrf=CI3PzHOIRTt77zGbzftkd8qy; Path=/
11:00:41.728 200 GET /api/options with 6666 bytes took 1ms
11:00:41.731 200 GET /api/tree with 158713 bytes took 2ms
11:00:41.733 Keyboard action showNoteInfo found in database, but not in action definition.
11:00:41.733 Keyboard action showLinkMap found in database, but not in action definition.
11:00:41.733 Keyboard action focusOnAttributes found in database, but not in action definition.
11:00:41.733 Keyboard action toggleZenMode found in database, but not in action definition.
11:00:41.733 200 GET /api/keyboard-actions with 11944 bytes took 1ms
11:00:41.734 200 GET /api/keyboard-shortcuts-for-notes with 2 bytes took 0ms
11:00:41.735 200 GET /api/script/widgets with 2930 bytes took 1ms
11:00:41.782 200 POST /api/tree/load with 2590 bytes took 1ms
11:00:41.787 200 GET /api/search/%23bookmarked%20or%20%23bookmarkFolder with 76 bytes took 1ms
11:00:41.811 200 POST /api/tree/load with 36348 bytes took 1ms
11:00:42.100 200 GET /api/notes/fkOUVezoxw17 with 2814 bytes took 1ms
11:00:42.101 200 GET /api/notes/fkOUVezoxw17/backlink-count with 11 bytes took 0ms
11:00:43.769 200 GET /api/script/startup with 2971 bytes took 1ms
11:00:43.770 200 POST /api/tree/load with 5389 bytes took 0ms
11:00:43.772 200 POST /api/tree/load with 4872 bytes took 0ms
11:00:43.772 200 POST /api/tree/load with 4872 bytes took 0ms
11:00:43.775 200 POST /api/tree/load with 4547 bytes took 0ms
11:00:45.418 Table counts: notes: 3041, note_revisions: 2964, branches: 3247, attributes: 4295, api_tokens: 0
11:00:45.513 All consistency checks passed with no errors detected (took 97ms)
11:00:51.602 200 GET /api/notes/bo0XWBoXQ3mw with 5640 bytes took 1ms
11:00:51.603 200 GET /api/notes/bo0XWBoXQ3mw/backlink-count with 11 bytes took 1ms
11:00:51.758 204 PUT /api/options with 0 bytes took 2ms
11:01:46.512 sync failed: Process exceeded time limit 60000
stack: Error: Process exceeded time limit 60000
    at Object.timeLimit (/opt/trilium-bin/resources/app.asar/src/services/utils.js:257:19)
    at syncRequest (/opt/trilium-bin/resources/app.asar/src/services/sync.js:299:32)
    at pushChanges (/opt/trilium-bin/resources/app.asar/src/services/sync.js:216:15)
    at /opt/trilium-bin/resources/app.asar/src/services/sync.js:37:23
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async Object.doExclusively (/opt/trilium-bin/resources/app.asar/src/services/sync_mutex.js:13:16)
    at async sync (/opt/trilium-bin/resources/app.asar/src/services/sync.js:27:16)
11:02:40.538 200 PUT /api/notes/bo0XWBoXQ3mw with 92 bytes took 7ms
11:02:56.532 sync failed: Process exceeded time limit 60000
stack: Error: Process exceeded time limit 60000
    at Object.timeLimit (/opt/trilium-bin/resources/app.asar/src/services/utils.js:257:19)
    at syncRequest (/opt/trilium-bin/resources/app.asar/src/services/sync.js:299:32)
    at doLogin (/opt/trilium-bin/resources/app.asar/src/services/sync.js:104:24)
    at login (/opt/trilium-bin/resources/app.asar/src/services/sync.js:94:18)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at async /opt/trilium-bin/resources/app.asar/src/services/sync.js:35:37
    at async Object.doExclusively (/opt/trilium-bin/resources/app.asar/src/services/sync_mutex.js:13:16)
    at async sync (/opt/trilium-bin/resources/app.asar/src/services/sync.js:27:16)
11:04:06.554 sync failed: Process exceeded time limit 60000

[zadam]

Any way to enable more verbose logging on the sync process?

No. But I don't think this would help. All this points to a network issue. Most probably you can reproduce the problem with curl.

[reefland]

Can you provide an example of how I could reproduce this with curl? I provided an example above using curl and which seemed worked fine, I'm not sure what else I can try via curl as a test. Here is the timed curl which was originally provided (private network):

$ time curl https://hpmediasrv.rich-durso.us/trilium-main/api/setup/status
{"isInitialized":true,"schemaExists":true,"syncVersion":23}

real    0m0.042s
user    0m0.003s
sys     0m0.008s

[zadam]

Sorry, I didn't notice you already tried with curl.

Honestly, I don't know what is making only the Trilium requests slow. Seems very weird.