"Pull: No Such File" Error

That’s expected and why it is trying to pull the file.

On both sides? The relevant one is the “sender”/SEPDJWL.

Ah right. Make sense. (Sorry - still getting my head round the details of this amazing app!)

I can’t believe it hasn’t scanned on SEPDJWL - it’s a Mac workstation which is in use most days. But I’ll get confirmation once I’m able to check on the system.

Sorry for the delay. I’ve checked, and SEPDJWL is set to scan every hour - last scanned within the hour…

Querying the API on here produces the following:

curl -k -X GET -H "X-API-Key: ******" 'http://localhost:8384/rest/db/file?folder=*****-*****&file=File/Path/Here'
{
  "availability": null,
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-02-25T15:54:07Z",
    "modifiedBy": "SEPDJWL",
    "mustRescan": false,
    "name": "File/Path/Here",
    "noPermissions": true,
    "numBlocks": 42,
    "permissions": "0644",
    "sequence": 1895513,
    "size": 5439245,
    "type": 0,
    "version": [
      "SEPDJWL:1",
      "UD7AGR2:2"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2019-02-25T15:54:07Z",
    "modifiedBy": "SEPDJWL",
    "mustRescan": false,
    "name": "File/Path/Here",
    "noPermissions": true,
    "numBlocks": 42,
    "permissions": "0644",
    "sequence": 1895513,
    "size": 5439245,
    "type": 0,
    "version": [
      "SEPDJWL:1",
      "UD7AGR2:2"
    ]
  }
}

Is that "availability": null significant?..

That looks exactly like expected, including the availability null bit. I am at a loss as to what’s happening, however you did just post in the case sensitivity topic: Are the two devices windows and mac by chance, and if so, are there any case differences? I can’t remember this kind of symptom with case problems, but anything is possible there…

Hi Simon:

Thanks for stopping by!

The cluster is 2 x Synology NAS units and a whole bunch of Macs (which is where my case sensitivity issue comes in - case-only renames get done on the Macs, which pull in duplicate copies on the NASes).

Here, the originating file is on one of the Macs, and I’m seeing the pull failure on the NAS units; however, I’m also seeing the same pull failure on at least one other Mac in the cluster - presumably more than one, but I haven’t examined the others yet.

There are 39 files spread across 3 subfolders of this shared folder which are failing to sync. I’ve examined the file paths for one of these files across four different machines and they all match as expected. There are a large number of files inside the folders containing the failed files, which have all otherwise synced successfully.

But of the two Macs and two NASes looked at, three of these machines have the old version of the file present.

Hello!

Apologies for bumping, but if there aren’t any thoughts about where it would be useful to look and diagnose further, I’ll touch the out of sync files to prompt a rescan of them - hopefully that’ll recognise their validity, and allow the sync to complete.

Is that the best course of action, or is there anything else I can do to help diagnose the underlying cause?

Thanks!

Hi, if you are hitting limits on number of open files, it can cause files to be “unopenable”, which leads to all kinds of odd stuff happening. The last update or two of syncthing I have noticed “too many open files” errors in the logs for both linux and mac computers in my cluster, which causes all manner of weird behavior. Are you seeing any “too many open files” errors in either your syncthing logs or system logs?

Ok, so with the rest excerpt you posted above it looks like Syncthing picks up on the change and sends that info to everyone, but they fail to request the data. You have also manually verified the case of the names match. Please shout if any of this is wrong. Next step would be to find out what exactly fails, i.e. enable model debug logging on the machine that has the updated file. Then pause/unpause the folder in question on another device, which does not have the updated file. There should line(s) like model@... REQ(in): *err* - *deviceid*: *folderid* / *filename* o=... s=....

Thanks Simon. I think this is the output that you’re after from the source machine (not the same file as detailed on the API calls above, but one of the other non-syncing files):

2019-04-12 09:44:54 model@0xc000136420 REQ(in): *******-*******-*******-*******-*******-*******-*******-*******: "*****-*****" / "File/Path/Here" o=786432 s=49985 t=false
2019-04-12 09:44:54 model@0xc000136420 recheckFile: *******-*******-*******-*******-*******-*******-*******-*******: "*****-*****" / "File/Path/Here" i=15: block index too far
2019-04-12 09:44:54 model@0xc000136420 REQ(in) failed validating data (<nil>): *******-*******-*******-*******-*******-*******-*******-*******: "*****-*****" / "File/Path/Here" o=786432 s=49985

The same three lines seem to be repeated for each of the failing files.

Thanks, that’s indeed good information. Did you recently change the large block setting on any/all of the devices for the involved folders?

Hi Simon - no, I haven’t touched that setting on any of the devices.

And is said setting true or false (if the folder is new enough, it’s true by default)? I am not saying that’s the reason, it’s just one parameter that’s important for trying to find the reason, given the error message.

Variable Size Blocks is off on - to my knowledge - all devices connected to this folder. All the devices were set up months ago, before VSB was a GUI option - so I’d be very surprised if it were enabled anywhere.

1 Like

Can’t edit because it’s too similar - but to clarify: VSB is set to false.

1 Like

I think I know the problem, at least I found a bug related to the error message you got. If I am right, then it means that those files were modified without changing size and modification times. This means either there is a program doing weird stuff when modifying these files (e.g. first setting size and modtime, then later writing the actual data) or those files changed due to disk corruption. Unless you know about such a program, make sure you have a backup or create one from the data on the unsynced devices.

If my hypothesis is right, touching (or whatever is the equivalent on your system that sets the modification time to now without changing the file itself) the affected file on the source and rescanning should fix the problem.

PR: https://github.com/syncthing/syncthing/pull/5648

Thanks very much - really appreciated!

Compared with the previous version of the file, the size and modification time are different… But I realise this might not be what you’re talking about!

The files in question were WAV files created by Apple’s Logic Pro X audio application; it’s possible that this does something unusual about pre-allocating the file before writing the data - but Syncthing is successfully syncing thousands of other files generated by this app, so I don’t think that’s likely.

That’s possible (and I do have backups thankfully) - but both the ‘old’ and ‘new’ versions of the file open and play as expected. But of course, it may only be a metadata chunk of the file which is affected by a corruption.

Sure. I’ll try that on a candidate file or two next week to ensure it goes smoothly, before applying it to all the outstanding files.

Thanks for your input; I appreciate that 39 files out of 132,000 (in this shared folder) is small fry and (hopefully) easily corrected - but I just wanted to give chance for any glitches to be identified before I wipe the evidence!

Puuuh, I was quite happy to read that, in the beginning of your post I thought I might be wrong all along, but that does sound somewhat plausible. The success of other files is probably, because for this bug to hit, the change must have occurred at the very end of the file, the rest of the file must have been the same. And in addition even then, it is still racy: The program preallocates, Syncthing gets an event from the filesystem, then waits for 10s to scan. Now if the program does the “real change” within those 10s, Syncthing will see the correct data, if it does so afterwards, it doesn’t.

Sounds like a good plan. Given the above, that the file is working and you having backup, there really isn’t much risk.

Thank you for that and in general for your responsive and very clear reporting, especially after the long silence on my part!

Hello:

That’s quite possible - looking at the file diffs and running a test just now, it looks like Logic is creating a graphic overview for the WAV file, then writing this to the end of original file, leaving the rest of it unchanged (save for a couple of bytes near the beginning). In doing so, it appears to be not updating the Modified Time of the file.

Sounds like my best bet is to back off the Fs Watcher Delay to give chance for the file to be completely written before it gets hashed - but it brings up an interesting question: what happens in Syncthing when an application updates a file without updating its Modified Time?

That or waiting for v1.1.3 (or v1.2.0), which is a bit of a stretch. And report to Apple/Logic devs that their program should behave nicely when changing a file :wink:
Syncthing recognises a change when either size or mtime changed. If both don’t change, nothing will happen until a remote either sends a change or request the file. In both cases Syncthing will then notice that the data on disk is not what is expected and will thus rescan, which is fine for a request and creates a conflict for the remote change. That is, except for the corner case you found and is fixed in the linked PR.

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