search

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

Trilium 0.46.5 - (Fatal) issue adding new notes #1778

Closed HiFiJ closed 3 years ago

HiFiJ commented 3 years ago

Hello,

thanks a lot for Trilium, it's amazing! I'm using it with a self hosted server and 4 synced desktop builds. Since update from 045.x to 0.46.5 on server and all desktop builds, I am experiencing severe problems when adding notes on the desktop builds. Adding the note on the desktop works including heading and contents, is correctly restored after exiting and reentering protected mode (all my notes are in protected mode). On the server I only get an "undefined" note entry with no contents. Trying to open/reopen the note gives me

Error when calling GET similar-notes/eG3mWDNikOqX: error - Internal Server Error and the server log shows

19:52:58.703 Content hash computation took 9ms 19:52:58.704 Slow 304 GET /api/sync/check took 11ms 19:53:35.405 200 GET /api/backend-log took 2ms 19:53:58.540 304 GET /api/setup/status took 1ms 19:53:58.563 200 POST /api/login/sync took 1ms 19:53:58.615 304 GET /api/sync/changed?lastEntityChangeId=15284 took 1ms 19:53:58.639 204 POST /api/sync/finished took 1ms 19:53:58.673 Content hash computation took 10ms 19:53:58.674 Slow 304 GET /api/sync/check took 11ms 19:54:20.563 304 GET /api/notes/RpYl08r6jipK took 1ms 19:54:20.599 204 PUT /api/options took 7ms 19:54:20.752 200 POST /api/tree/load took 0ms 19:54:20.827 304 GET /api/notes/EQV4q7yIHdNb took 1ms 19:54:20.880 304 GET /api/notes/Vnx5w5wwLBMG took 1ms 19:54:21.629 Slow 200 GET /api/similar-notes/RpYl08r6jipK took 28ms 19:54:21.632 304 GET /api/notes/RpYl08r6jipK/revisions took 0ms 19:54:21.662 204 PUT /api/options took 3ms 19:54:21.688 304 GET /api/notes/eG3mWDNikOqX took 1ms 19:54:22.595 200 GET /api/similar-notes/eG3mWDNikOqX took 1ms 19:54:22.595 ERROR: get /api/similar-notes/:noteId threw exception: Error: Date limits failed with Invalid time value, entity: {"noteId":"eG3mWDNikOqX","isProtected":false,"isDecrypted":true,"ownedAttributes":[],"inheritableAttributeCache":[],"targetRelations":[],"contentSize":null,"noteSize":null,"revisionCount":null} at Object.findSimilarNotes (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/note_cache/similarity.js:246:15) at getSimilarNotes (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/api/similar_notes.js:15:36) at Function.cb (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/routes.js:96:34) at Function.sqliteTransaction (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/better-sqlite3/lib/transaction.js:58:24) at Object.transactional (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/sql.js:234:52) at /home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/routes.js:98:44 at /home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/cls-hooked/context.js:118:13 at Namespace.run (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/cls-hooked/context.js:97:5) at Namespace.runAndReturn (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/cls-hooked/context.js:117:8) at Object.init (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/cls.js:5:22) 19:54:22.600 304 GET /api/notes/eG3mWDNikOqX/revisions took 1ms 19:54:22.649 JS Error: Error when calling GET similar-notes/eG3mWDNikOqX: error - Internal Server Error Stack: w@https://XXXX.net:8080/app-dist/desktop.js:1:86327 throwError@https://XXXX.net:8080/app-dist/desktop.js:1:64325 c@https://XXXX.net:8080/app-dist/desktop.js:1:61330

19:54:26.586 204 POST /api/recent-notes took 3ms 19:54:58.538 304 GET /api/setup/status took 0ms 19:54:58.564 200 POST /api/login/sync took 1ms 19:54:58.614 304 GET /api/sync/changed?lastEntityChangeId=15284 took 1ms 19:54:58.637 204 POST /api/sync/finished took 0ms 19:54:58.672 Content hash computation took 8ms 19:54:58.673 Slow 304 GET /api/sync/check took 10ms

Would this look like a bug, or something else? I tried vacuuming the DB, ran "Fix consistency errors" and "Full sync" two times, but got this issue repeatedly. Thanks for any clues, glad to help with further logs etc.,

Joost

PS: Desktop log does not show any signs of error:

19:44:50.016 App HTTP server starting up at port 37840 19:44:50.016 { "appVersion": "0.46.5", "dbVersion": 183, "syncVersion": 20, "buildDate": "2021-03-14T22:56:27+01:00", "buildRevision": "6c8d20288df302f3a415bd1bdcace98bf29d4bf6", "dataDirectory": "/home/XXXX/.local/share/trilium-data", "clipperProtocolVersion": "1.0" } 19:44:50.031 CPU model: Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz, logical cores: 8 freq: 3627 Mhz 19:44:50.034 Listening on port 37840 19:44:50.073 Registered global shortcut Ctrl+Alt+P for action createNoteIntoInbox 19:44:50.138 Generated CSRF token KwxlTS7T-617JAkAfwVZRaBRSoU8stltqltk with secret _csrf=ExyG-qtzpqXoun8npq9tvHqQ; Path=/ 19:44:50.159 Slow 200 GET / took 22ms 19:44:50.312 401 GET /api/notes/download/BgDY5EOtFWuZ took 1ms 19:44:50.314 401 GET /api/notes/download/q7yCiQxcTRbh took 1ms 19:44:50.344 200 GET /api/options took 1ms 19:44:50.345 200 GET /api/tree took 0ms 19:44:50.348 200 GET /api/keyboard-actions took 1ms 19:44:50.350 200 GET /api/keyboard-shortcuts-for-notes took 0ms 19:44:50.351 200 GET /api/script/widgets took 1ms 19:44:50.431 200 GET /api/tree?subTreeNoteId=8EhxI37CVQ6L took 1ms 19:44:50.797 200 GET /api/notes/QVxSaWlRwA8E took 8ms 19:44:51.785 Slow 200 GET /api/similar-notes/QVxSaWlRwA8E took 25ms 19:44:51.788 200 GET /api/notes/QVxSaWlRwA8E/revisions took 1ms 19:44:52.387 200 GET /api/script/startup took 2ms 19:44:53.188 Nothing to push 19:44:53.237 Sending message to all clients: {"type":"sync-pull-in-progress"} 19:44:53.261 Pulled 2 changes in 1 KB, starting at entityChangeId=15275 in 48ms and applied them in 24ms, 0 outstanding pulls 19:44:53.289 200 GET /api/notes/QVxSaWlRwA8E took 0ms 19:44:53.317 200 GET /api/autocomplete?query=&activeNoteId=null took 4ms 19:44:53.337 204 PUT /api/options took 2ms 19:44:53.362 Sending message to all clients: {"type":"sync-pull-finished"} 19:44:53.363 Finished pull 19:44:53.364 Nothing to push 19:44:53.401 200 GET /api/notes/liqOERLIF5WX took 1ms 19:44:53.439 200 POST /api/tree/load took 0ms 19:44:53.475 Content hash computation took 12ms 19:44:53.475 Content hash checks PASSED 19:44:54.337 204 PUT /api/options took 2ms 19:44:54.389 200 GET /api/similar-notes/liqOERLIF5WX took 7ms 19:44:54.392 200 GET /api/notes/liqOERLIF5WX/revisions took 1ms 19:44:56.892 Slow 200 POST /api/login/protected took 216ms 19:44:56.894 200 GET /api/tree took 0ms 19:44:56.895 200 POST /api/tree/load took 0ms 19:44:56.911 200 GET /api/tree?subTreeNoteId=8EhxI37CVQ6L took 0ms 19:44:56.913 200 GET /api/notes/liqOERLIF5WX took 1ms 19:44:56.967 Slow 200 GET /api/similar-notes/liqOERLIF5WX took 54ms 19:44:56.970 200 GET /api/notes/liqOERLIF5WX/revisions took 1ms 19:44:57.463 200 GET /api/notes/GV84vZ5fMB4i took 2ms 19:44:57.490 200 GET /api/notes/9y1BFL9nf7bV took 2ms 19:44:58.374 204 POST /api/recent-notes took 6ms 19:45:09.953 Table counts: notes: 286, note_revisions: 600, branches: 310, attributes: 286, api_tokens: 0 19:45:09.963 All consistency checks passed (took 11ms) 19:45:12.758 200 POST /api/notes/jiI2l1KUxVks/children?target=into&targetBranchId=undefined took 7ms 19:45:12.762 200 POST /api/tree/load took 1ms 19:45:12.810 200 GET /api/notes/eG3mWDNikOqX took 0ms 19:45:12.847 204 PUT /api/options took 1ms 19:45:13.836 Slow 200 GET /api/similar-notes/eG3mWDNikOqX took 41ms 19:45:13.839 200 GET /api/notes/eG3mWDNikOqX/revisions took 0ms 19:45:13.840 200 POST /api/tree/load took 0ms 19:45:15.526 Slow 200 PUT /api/notes/eG3mWDNikOqX/change-title took 15ms 19:45:15.545 200 GET /api/notes/eG3mWDNikOqX took 3ms 19:45:15.574 Slow 200 GET /api/similar-notes/eG3mWDNikOqX took 26ms 19:45:16.521 200 PUT /api/notes/eG3mWDNikOqX/change-title took 4ms 19:45:16.551 Slow 200 GET /api/similar-notes/eG3mWDNikOqX took 15ms 19:45:17.786 204 POST /api/recent-notes took 2ms 19:45:18.775 200 PUT /api/notes/eG3mWDNikOqX took 2ms 19:45:18.781 200 GET /api/notes/eG3mWDNikOqX took 1ms 19:45:26.505 200 GET /api/notes/8EhxI37CVQ6L took 1ms 19:45:26.681 204 PUT /api/options took 0ms 19:45:27.536 Slow 200 GET /api/similar-notes/8EhxI37CVQ6L took 51ms 19:45:27.538 200 GET /api/notes/8EhxI37CVQ6L/revisions took 1ms 19:45:27.539 200 POST /api/tree/load took 0ms 19:45:28.100 200 POST /api/notes/eG3mWDNikOqX/children?target=into&targetBranchId=undefined took 8ms 19:45:28.111 200 POST /api/tree/load took 1ms 19:45:28.156 200 GET /api/notes/MQ2l0oFK0sGb took 0ms 19:45:28.200 204 PUT /api/options took 0ms 19:45:28.214 204 PUT /api/branches/oiw6hpBhbs6j/expanded/1 took 1ms 19:45:29.161 Slow 200 GET /api/similar-notes/MQ2l0oFK0sGb took 14ms 19:45:29.162 200 GET /api/notes/MQ2l0oFK0sGb/revisions took 0ms 19:45:33.140 204 POST /api/recent-notes took 1ms 19:45:34.954 Sending message to all clients: {"type":"task-progress-count","taskId":"iCLtvEpcVc","taskType":"delete-notes","progressCount":0} 19:45:34.957 Deleting note MQ2l0oFK0sGb 19:45:34.958 Sending message to all clients: {"type":"task-succeeded","taskId":"iCLtvEpcVc","taskType":"delete-notes"} 19:45:34.963 Slow 204 DELETE /api/notes/MQ2l0oFK0sGb?taskId=iCLtvEpcVc&last=true took 10ms 19:45:34.989 200 GET /api/notes/MQ2l0oFK0sGb took 1ms 19:45:35.011 200 GET /api/autocomplete?query=&activeNoteId=null took 1ms 19:45:35.016 204 PUT /api/options took 1ms 19:45:35.049 200 GET /api/notes/eG3mWDNikOqX took 1ms 19:45:36.022 204 PUT /api/options took 2ms 19:45:36.070 Slow 200 GET /api/similar-notes/eG3mWDNikOqX took 32ms 19:45:36.072 200 GET /api/notes/eG3mWDNikOqX/revisions took 0ms 19:45:40.033 204 POST /api/recent-notes took 2ms 19:45:41.274 Slow 200 GET /api/recent-changes/root took 57ms 19:45:41.279 200 POST /api/tree/load took 1ms 19:45:44.262 200 GET /api/notes/eG3mWDNikOqX took 2ms 19:45:50.118 Pushing 6 sync changes in 39ms 19:45:50.119 Nothing to push 19:45:50.180 Pulled 6 changes in 3 KB, starting at entityChangeId=15278 in 60ms and applied them in 0ms, 0 outstanding pulls 19:45:50.277 Finished pull 19:45:50.277 Nothing to push 19:45:50.400 Content hash computation took 31ms 19:45:50.400 Content hash checks PASSED 19:46:50.077 Nothing to push 19:46:50.107 Finished pull 19:46:50.108 Nothing to push 19:46:50.182 Content hash computation took 12ms 19:46:50.183 Content hash checks PASSED 19:47:50.033 Nothing to push 19:47:50.059 Finished pull 19:47:50.060 Nothing to push 19:47:50.152 Content hash computation took 22ms 19:47:50.153 Content hash checks PASSED 19:48:50.032 Nothing to push 19:48:50.059 Finished pull 19:48:50.059 Nothing to push 19:48:50.175 Content hash computation took 22ms 19:48:50.176 Content hash checks PASSED 19:49:50.001 Created backup at /home/jc/.local/share/trilium-data/backup/backup-daily.db 19:49:50.076 Nothing to push 19:49:50.106 Finished pull 19:49:50.106 Nothing to push 19:49:50.191 Content hash computation took 22ms 19:49:50.192 Content hash checks PASSED 19:50:50.049 Nothing to push 19:50:50.078 Finished pull 19:50:50.078 Nothing to push

HiFiJ commented 3 years ago

Another problem: 1) Created an unprotected note on the server with content 2) After sync, the note opens correctly on the server and on the desktop build 3) Setting it to protected on the desktop and syncing leads to (server log):

21:24:01.155 204 POST /api/sync/finished took 1ms 21:24:01.205 Content hash computation took 9ms 21:24:01.207 Slow 200 GET /api/sync/check took 12ms 21:24:05.468 Received request to trigger sync now. 21:24:05.468 200 POST /api/sync/now took 1ms 21:24:12.636 304 GET /api/setup/status took 1ms 21:24:12.667 200 POST /api/login/sync took 1ms 21:24:12.778 304 GET /api/sync/changed?lastEntityChangeId=15324 took 1ms 21:24:12.812 Slow 204 POST /api/sync/finished took 10ms 21:24:12.849 Content hash computation took 10ms 21:24:12.850 Slow 304 GET /api/sync/check took 11ms 21:24:20.220 Slow 200 POST /api/login/protected took 119ms 21:24:20.296 304 GET /api/tree took 1ms 21:24:20.343 200 POST /api/tree/load took 1ms 21:24:20.484 ERROR: get /api/notes/:noteId threw exception: Error: error:0606506D:digital envelope routines:EVP_DecryptFinal_ex:wrong final block length at Decipheriv.final (internal/crypto/cipher.js:172:29) at Object.decrypt (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/data_encryption.js:71:91) at Object.decrypt (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/protected_session.js:64:34) at Note.getContent (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/entities/note.js:87:91) at getNote (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/api/notes.js:19:29) at Function.cb (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/routes.js:96:34) at Function.sqliteTransaction (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/better-sqlite3/lib/transaction.js:58:24) at Object.transactional (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/sql.js:234:52) at /home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/routes.js:98:44 at /home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/cls-hooked/context.js:118:13 21:24:20.486 500 GET /api/notes/kodkFNn2kAMZ took 3ms 21:24:20.488 200 GET /api/similar-notes/kodkFNn2kAMZ took 1ms 21:24:20.488 ERROR: get /api/similar-notes/:noteId threw exception: Error: error:0606506D:digital envelope routines:EVP_DecryptFinal_ex:wrong final block length at Decipheriv.final (internal/crypto/cipher.js:172:29) at Object.decrypt (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/data_encryption.js:71:91) at Object.decrypt (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/protected_session.js:64:34) at Note.getContent (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/entities/note.js:87:91) at buildRewardMap (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/note_cache/similarity.js:127:36) at Object.findSimilarNotes (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/note_cache/similarity.js:249:23) at getSimilarNotes (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/api/similar_notes.js:15:36) at Function.cb (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/routes/routes.js:96:34) at Function.sqliteTransaction (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/node_modules/better-sqlite3/lib/transaction.js:58:24) at Object.transactional (/home/jc/Trilium-PackagedServer/trilium-linux-x64-server/src/services/sql.js:234:52) 21:24:20.491 200 GET /api/notes/kodkFNn2kAMZ/revisions took 1ms 21:24:20.558 JS Error: Error when calling GET similar-notes/kodkFNn2kAMZ: error - Internal Server Error Stack: w@https://XXXXX.net:8080/app-dist/desktop.js:1:86327 throwError@https://XXXXX.net:8080/app-dist/desktop.js:1:64325 c@https://XXXXX.net:8080/app-dist/desktop.js:1:61330

21:24:20.558 JS Error: Error when calling GET notes/kodkFNn2kAMZ: error - Internal Server Error Stack: w@https://XXXX.net:8080/app-dist/desktop.js:1:86327 throwError@https://XXXX.net:8080/app-dist/desktop.js:1:64325 c@https://XXXXX.net:8080/app-dist/desktop.js:1:61330

zadam commented 3 years ago

Hi, thank you for reporting this issue!

I managed to reproduce similar problems like you describe with protected notes.

I will try to fix this tomorrow (I already have some idea what might be causing this) and subsequently release a fixed version. In the meantime I recommend to not create protected notes.

zadam commented 3 years ago

Fix has been releases in 0.46.6.

The previously affected notes are however not fixed. To remedy this situation, you should trigger sync of the affected notes on the source instance - e. g. using context menu on the tree - advanced - force note sync or by just editing them (adding space etc.). This will sync them again and fix the issue on other instances.

HiFiJ commented 3 years ago

Thanks a lot for the very fast response, great!! Best regards,

Joost