Some Files Refusing To Sync

Hello:

Sorry - me again. Feels like I’m just bringing issue after issue to the board… I hope it’s a net positive…

I’ve got a setup where 6 files are refusing to sync on one system. They haven’t been changed in a long time, and I could just touch them to resolve it - but whilst I’ve got a bit of time, I thought I’d dig into the logs to see if there’s anything useful underlying it.

image

Here’s a log extract:

2020-04-03 12:05:11 My ID: GKRQ2C4-*******-*******-*******-*******-*******-*******-*******
2020-04-03 12:05:12 Single thread SHA256 performance is 196 MB/s using minio/sha256-simd (154 MB/s using crypto/sha256).
2020-04-03 12:05:13 Hashing performance is 168.96 MB/s
2020-04-03 12:05:13 Overall send rate is unlimited, receive rate is unlimited
2020-04-03 12:05:13 Using discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2020-04-03 12:05:13 Using discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2020-04-03 12:05:13 Using discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2020-04-03 12:05:13 TCP listener ([::]:22000) starting
2020-04-03 12:05:13 Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
2020-04-03 12:05:13 QUIC listener ([::]:22000) starting
2020-04-03 12:05:13 ...
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 1
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 2
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:12 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 3
2020-04-03 14:38:12 Folder "Audio" (pcggy-*****) isn't making sync progress - retrying in 1h4m0.060438791s.
...
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 pulling
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 1
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 2
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:16 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 3
2020-04-03 14:38:16 Folder "Audio" (pcggy-*****) isn't making sync progress - retrying in 1h4m0.066374704s.
...
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 pulling
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 1
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 2
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:40 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 3
2020-04-03 14:38:40 Folder "Audio" (pcggy-*****) isn't making sync progress - retrying in 1h4m0.051922556s.
2020-04-03 14:38:40 progress emitter: bytes completed for pcggy-*****: 0
...
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 pulling
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
...
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 1
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 2
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/3>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/4>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/5>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/6>
2020-04-03 14:38:46 sendreceive/pcggy-*****@0xc00013a600 changed 6 on try 3
2020-04-03 14:38:46 Folder "Audio" (pcggy-*****) isn't making sync progress - retrying in 1h4m0.081714824s.
...
2020-04-03 14:38:48 sendreceive/pcggy-*****@0xc00013a600 copiers: 2 pullerPendingKiB: 32768
2020-04-03 14:38:48 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/1>
2020-04-03 14:38:48 sendreceive/pcggy-*****@0xc00013a600 taking shortcut on <file/path/2>

And looking on the API for the first file:

{
  "availability": [
    {
      "id": "LE3IMUG-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    },
    {
      "id": "VA54OKA-*******-*******-*******-*******-*******-*******-*******",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-03-07T07:16:50Z",
    "modifiedBy": "GKRQ2C4",
    "mustRescan": false,
    "name": "<file/path/1>",
    "noPermissions": false,
    "numBlocks": 1,
    "permissions": "0644",
    "sequence": 334998,
    "size": 8624,
    "type": "FILE",
    "version": [
      "GKRQ2C4:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-03-07T07:16:50Z",
    "modifiedBy": "GKRQ2C4",
    "mustRescan": false,
    "name": "<file/path/1>",
    "noPermissions": false,
    "numBlocks": 1,
    "permissions": "0644",
    "sequence": 525948,
    "size": 8624,
    "type": "FILE",
    "version": [
      "GKRQ2C4:1"
    ]
  }
}

Is there anything useful here for me to dig into further, or should I just touch the files and be done with it?

Thanks!

The file looks in sync according to the API, and shortcut failing feels weird.

I should note there are some unusual characters in the file path - the API call for it looks like this:

...http://127.0.0.1:7070/rest/db/file?folder=pcggy-*****&file=%E2%80%A2%C2%A0Logic%20Projects/..

But there are plenty of other files under that path that have synced correctly…

Hold on, I think there is a bug here.

Can you run the index check tool?

There are no failed items in the UI by the looks of it?

Of course. One moment…

That’s right - just Out of Sync items constantly. The folder status mainly shows Out of Sync, then flips to Preparing to Sync every so often, then back.

The file being considered “needed” while it’s not is definitely a bug, probably going to be hard to find out how that happened and fix it.

A separate “issue” is that in db we just do nothing after pulling, because the new and old file are the same. That’s the intended behaviour, however I don’t think it’s ever expected to happen that we receive an update for something that wasn’t updated. That might justify checking such a file for correctness, which would then discover the incorrect need entry and clean that out.

Ok - got the output here - lots of Duplicate sequence entry and Sequence mismatch reports. Is there somewhere private I can send it to you?

I’ll get a copy of the database itself too, if that would be helpful…

What version are you on?

1.4.0 - set to stable releases.

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.