Joplin: Desktop sync -- sync not working -- Error: URI malformed - only index.txt gets updated

[tangodev]

Originally reported here: https://discourse.joplinapp.org/t/error-uri-malformed-only-index-txt-gets-updated-sync-not-working/6286

When I was working in Joplin and adding pages through the clipper, sync stopped. This is how my Nextcloud window started to look:

I could add notes without issue to Joplin, but they would not get flushed to disk. I started seeing this error in Joplin:

Created remote items: 1.
Completed: 2020-02-25 20:03
Last error: Error: URI malformed

Keep in mind that the above date is only a rough estimate.

Environment

Joplin version: 1.0.179
Platform: Linux
OS specifics: Ubuntu 18.04 LTS (KDE Neon)
Browser: Brave Version 1.2.43 Chromium: 79.0.3945.130 (Official Build) (64-bit)
Clipper version: 1.0.19

Steps to reproduce

The issue may be related to the webclipper, but I have about a dozen of pages that may be suspects. That's the amount of notes I added between when sync last worked and when I verified that it no longer worked. I took a look both into the logs and into the sqlite database but I need help to find the culprit.

As far as I remember, the note in question didn't appear in Joplin at all. But I was tired and maybe I just didn't notice. Another symptom that may or may not be related is that the clipper should always display the last (sub)notebook that got used. During that session I noticed it would sometimes skip and suggest a different (sub)notebook.

After I find the specific URL, the steps should be:

1. Open website in web browser
2. Use web clipper (I'm 90% sure I used full HTML clip)
3. Observe results of next sync

Describe what you expected to happen

After using the clipper the note should appear in Joplin and then get synced to the back-end (disk in this case).

Logfile

The above may be a red herring, because when I click "SYNC" in the bottom left corner, those errors don't multiply.

In the logs (.config/joplin-desktop/log.txt) I'm seeing this:

2020-02-25 19:25:58: "Starting scheduled sync"
2020-02-25 19:25:58: "Error: URI malformed
Error: URI malformed
    at EncryptionService.encrypt (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:298:11)
    at EncryptionService.encryptAbstract_ (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:402:33)
    at async EncryptionService.encryptString (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:489:3)
    at async Function.serializeForSync (/tmp/.mount_JoplinMgdiNs/resources/app/lib/models/BaseItem.js:344:22)
    at async Synchronizer.start (/tmp/.mount_JoplinMgdiNs/resources/app/lib/synchronizer.js:457:25)
    at async timeoutCallback (/tmp/.mount_JoplinMgdiNs/resources/app/lib/registry.js:112:24)"
2020-02-25 19:25:58: "Operations completed: "
2020-02-25 19:25:58: "createRemote: 1"
2020-02-25 19:25:58: "Total folders: 50"
2020-02-25 19:25:58: "Total notes: 192"
2020-02-25 19:25:58: "Total resources: 934"
2020-02-25 19:25:58: "There was some errors:"
2020-02-25 19:25:58: "Error: URI malformed
Error: URI malformed
    at EncryptionService.encrypt (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:298:11)
    at EncryptionService.encryptAbstract_ (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:402:33)
    at async EncryptionService.encryptString (/tmp/.mount_JoplinMgdiNs/resources/app/lib/services/EncryptionService.js:489:3)
    at async Function.serializeForSync (/tmp/.mount_JoplinMgdiNs/resources/app/lib/models/BaseItem.js:344:22)
    at async Synchronizer.start (/tmp/.mount_JoplinMgdiNs/resources/app/lib/synchronizer.js:457:25)
    at async timeoutCallback (/tmp/.mount_JoplinMgdiNs/resources/app/lib/registry.js:112:24)"
2020-02-25 19:26:36: "Scheduling sync operation..."
2020-02-25 19:26:42: "Scheduling sync operation..."
2020-02-25 19:26:46: "SearchEngine: Updating FTS table..."
2020-02-25 19:26:47: "SearchEngine: Updated FTS table in 580ms. Inserted: 1. Deleted: 0"
2020-02-25 19:27:04: "Scheduling sync operation..."
2020-02-25 19:27:14: "SearchEngine: Updating FTS table..."
2020-02-25 19:27:14: "SearchEngine: Updated FTS table in 491ms. Inserted: 1. Deleted: 0"
2020-02-25 19:27:20: "RevisionService::maintenance: Starting..."

The above is the first occurrence of the URI error I saw in the logs. I don't know which object is causing this.

I'd like to ask for help in understanding how to translate notes.created_time and notes.updated_time from the sqlite database into a normal date (because the Linux date command didn't help me here). With that info I should know which note got added before 19:25:58 and replicate the issue.

Thank you in advance!

ALSO: Is this normal that I'm seeing BLOBs in the notes.body column sometimes?

[tangodev]

I tried to recreate this in a VM by taking clips from URLs that I was 99% sure were in the batch when the error happened. I used simple clip, full page and full page HTML on them.

The error didn't appear. I did however change the version of my browser in the meantime to this:
Version 1.4.95 Chromium: 80.0.3987.122 (Official Build) (64-bit)

[laurent22]

@tangodev, are you still able to replicate this issue? If so, please could you try with the latest version: https://github.com/laurent22/joplin/releases/tag/v1.0.189

It won't fix the issue unfortunately, but it will give more info in the error message, in particular it will tell you the item ID. Then if you could do the following that would be great:

• Export all your data to RAW (Joplin Export Directory)
• In there, find the file with the same item ID as in the error.
• Then please post the file here as an attachment (or send it to me via PM on the forum)

[tangodev]

Hello @laurent22
got it:

2020-03-06 08:53:47: "Sync: starting: Starting synchronisation to target 2... [1583484827043]"
2020-03-06 08:53:47: "mkdir /home/td/Nextcloud/Joplin/.sync"
2020-03-06 08:53:47: "mkdir /home/td/Nextcloud/Joplin/.lock"
2020-03-06 08:53:47: "mkdir /home/td/Nextcloud/Joplin/.resource"
2020-03-06 08:53:47: "list /home/td/Nextcloud/Joplin"
2020-03-06 08:53:47: "get /home/td/Nextcloud/Joplin/.sync/version.txt"
2020-03-06 08:53:47: "put /home/td/Nextcloud/Joplin/.sync/version.txt", "null"
2020-03-06 08:53:47: "stat /home/td/Nextcloud/Joplin/92d67e78eb8840c3a00a7e90a80edea1.md"
2020-03-06 08:53:47: "Sync: createRemote: remote does not exist, and local is new and has never been synced: Note: (Local 92d67e78eb8840c3a00a7e90a80edea1)"
2020-03-06 08:53:47: "Error: Could not encrypt item 92d67e78eb8840c3a00a7e90a80edea1: SJCL error: URI malformed
Error: Could not encrypt item 92d67e78eb8840c3a00a7e90a80edea1: SJCL error: URI malformed
    at Function.serializeForSync (/tmp/.mount_JoplinuI2RP5/resources/app.asar/lib/models/BaseItem.js:351:10)"
2020-03-06 08:53:47: "Sync: finished: Synchronisation finished [1583484827043]"

I've found the note and I'll PM you.

[laurent22]

@tangodev, could you try the latest release to see if it fixes your issue? https://github.com/laurent22/joplin/releases/tag/v1.0.192

[tangodev]

@laurent22 it works!

2020-03-07 17:26:32: "Profile directory: /home/td/.config/joplin-desktop"
2020-03-07 17:26:32: "Trying to load 1 master keys..."
2020-03-07 17:26:33: "Loaded master keys: 1"
2020-03-07 17:26:33: "ResourceFetcher: Auto-add resources: Mode: always"
2020-03-07 17:26:33: "ResourceFetcher: Auto-added resources: 0"
2020-03-07 17:26:33: "Refreshing notes:", "null", "null"
2020-03-07 17:26:33: "Trying to load 1 master keys..."
2020-03-07 17:26:33: "Loaded master keys: 1"
2020-03-07 17:26:33: "Scheduling sync operation..."
2020-03-07 17:26:33: "Setting up recurrent sync with interval 300"
2020-03-07 17:26:33: "Trying to load 1 master keys..."
2020-03-07 17:26:33: "Loaded master keys: 1"
2020-03-07 17:26:33: "Scheduling sync operation..."
2020-03-07 17:26:33: "Trying to load 1 master keys..."
2020-03-07 17:26:33: "Loaded master keys: 1"
2020-03-07 17:26:33: "Scheduling sync operation..."
2020-03-07 17:26:33: "Scheduling sync operation..."
2020-03-07 17:26:33: "RevisionService::runInBackground: Starting background service with revision collection interval 600000"
2020-03-07 17:26:34: "Refreshing notes:", "2", "c6f072fa560340e8a87636ce9ae6fb03"
2020-03-07 17:26:34: "DecryptionWorker: starting decryption..."
2020-03-07 17:26:35: "DecryptionWorker: completed decryption."
2020-03-07 17:26:37: "RevisionService::maintenance: Starting..."
2020-03-07 17:26:37: "RevisionService::maintenance: Service is enabled"
2020-03-07 17:26:37: "RevisionService::collectRevisions: Created revisions for 0 notes"
2020-03-07 17:26:37: "RevisionService::maintenance: Done in 109ms"
2020-03-07 17:26:43: "SearchEngine: Updating FTS table..."
2020-03-07 17:26:43: "SearchEngine: Updated FTS table in 3ms. Inserted: 0. Deleted: 0"
2020-03-07 17:26:43: "Preparing scheduled sync"
2020-03-07 17:26:43: "Starting scheduled sync"
2020-03-07 17:26:43: "Sync: starting: Starting synchronisation to target 2... [1583602003295]"
2020-03-07 17:26:43: "mkdir /home/td/Nextcloud/Joplin/.sync"
2020-03-07 17:26:43: "mkdir /home/td/Nextcloud/Joplin/.lock"
2020-03-07 17:26:43: "mkdir /home/td/Nextcloud/Joplin/.resource"
2020-03-07 17:26:43: "list /home/td/Nextcloud/Joplin"
2020-03-07 17:26:43: "get /home/td/Nextcloud/Joplin/.sync/version.txt"
2020-03-07 17:26:43: "put /home/td/Nextcloud/Joplin/.sync/version.txt", "null"
2020-03-07 17:26:43: "stat /home/td/Nextcloud/Joplin/92d67e78eb8840c3a00a7e90a80edea1.md"
2020-03-07 17:26:43: "Sync: createRemote: remote does not exist, and local is new and has never been synced: Note: (Local 92d67e78eb8840c3a00a7e90a80edea1)"
2020-03-07 17:26:43: "put /home/td/Nextcloud/Joplin/92d67e78eb8840c3a00a7e90a80edea1.md", "null"

<<<REDACTED>>>

:D thank you!