Request from ... for file ... in unshared folder "..."

jazzl0ver · October 11, 2017, 2:49pm

Hi. I’m getting the strange GUI notice every time a folder is updated on a source host:

2017-10-11 09:58:48: Request from st01.... for file sysstates/vm-dc2/WindowsImageBackup/vm-dc2/Backup 2017-10-10 213016/22a29103-870e-11e0-a053-806e6f6e7763.vhd in unshared folder "i4udq-q2yx2"

The same message appears in the console with WARNING prefix. The source host (the sender) is permitted to send only. The folder (“i4udq-q2yx2”) is shared between that two hosts.

Please, help me to find out what’s going on.

OS on both hosts - CentOS 7 Syncthing versions - v0.14.39, Linux (64 and 32 bits)

AudriusButkevicius · October 11, 2017, 4:22pm

Can you post config.xml from both sides?

jazzl0ver · October 11, 2017, 5:29pm

filer-1: https://paste.ee/p/nuyAz st01 - see the next reply (I’m a new user - can’t post two links)

I obfuscated the sensitive parts with “skip” word and removed lines for other folders and devices.

jazzl0ver · October 11, 2017, 5:29pm

st01: https://paste.ee/p/VPj5C

AudriusButkevicius · October 11, 2017, 5:36pm

Is this easily reproduced or a one off?

jazzl0ver · October 12, 2017, 11:27am

I’m getting this notice every day ('cos I’m backing up Windows every day). I clear it up (by clicking OK button) and get the notice again on the next day:

AudriusButkevicius · October 12, 2017, 11:39am

I mean if you restart syncthing, does that still happen? Is there more than one source of these files, as I suspect if there wasn’t the other device would fail to sync?

jazzl0ver · October 12, 2017, 1:44pm

I’ve just restarted both syncthing daemons. Will let you know tomorrow. Thank you!

No, there’s only one source of that files.

jazzl0ver · October 13, 2017, 4:59pm

It appears the issue has gone after restart. Thanks a lot!

AudriusButkevicius · October 13, 2017, 5:31pm

I suspect it’s some sort of race condition, but it’s not clear how it happens, and I’d expect sync not to work once you hit this as the message comes from the same location that checks permissions.

jazzl0ver · October 16, 2017, 9:40am

Hi Audrius,

Just got that again on Oct 15:

 2017-10-15 09:59:42: Request from st01.skip for file sysstates/vm-dc1/WindowsImageBackup/vm-dc1/Backup 2017-10-14 223007/33a29103-870e-11e0-a053-806e6f6e6963.vhd in unshared folder "i4udq-q2yx2"

Any ideas how to get that fixed?

AudriusButkevicius · October 16, 2017, 10:54am

I mean, you are the only one experiencing this, so there is definately something wrong with your config.

The code is here:

github.com

syncthing/syncthing/blob/master/lib/model/model.go#L1244


			if device == deviceCfg.DeviceID {
				// Already shared nothing todo.
				return false
			}
		}
		cfg.Devices = append(cfg.Devices, config.FolderDeviceConfiguration{
			DeviceID: deviceCfg.DeviceID,
		})
		w, _ := m.cfg.SetFolder(cfg)
		w.Wait()
		l.Infof("Shared %s with %s due to auto-accept", folder.ID, deviceCfg.DeviceID)
		return true
	}
}


func (m *Model) introduceDevice(device protocol.Device, introducerCfg config.DeviceConfiguration) {
	addresses := []string{"dynamic"}
	for _, addr := range device.Addresses {
		if addr != "dynamic" {
			addresses = append(addresses, addr)
		}

There is no way the file is getting synced, perhaps the folder/device is paused or something like that?

jazzl0ver · October 16, 2017, 4:30pm

I have one idea. 1st of all, the sub-folder “Backup 2017-10-14 223007” do not exist anymore on both hosts (source and destination). What does exist - the folder “Backup 2017-10-15 223008”: Source:

[root@filer-1 vm-dc1]# pwd
/zmir/backup/sysstates/vm-dc1/WindowsImageBackup/vm-dc1
[root@filer-1 vm-dc1]# find . -type f -ls | grep 33a29103-870e-11e0-a053-806e6f6e6963.vhd
4730735 15975399 -rwxrwxr-x   1 administrator domain users 29239443456 Oct 15 22:57 ./Backup\ 2017-10-15\ 223008/33a29103-870e-11e0-a053-806e6f6e6963.vhd

Destination:

[root@st01 vm-dc1]# pwd
/backup/filer-1/sysstates/vm-dc1/WindowsImageBackup/vm-dc1
[root@st01 vm-dc1]# find . -type f -ls | grep 33a29103-870e-11e0-a053-806e6f6e6963.vhd
230546325 17074352 -rwxr-xr-x   1 bacula   disk     29239443456 Oct 16 16:24 ./Backup\ 2017-10-15\ 223008/.syncthing.33a29103-870e-11e0-a053-806e6f6e6963.vhd.tmp
[root@st01 vm-dc1]# date
Mon Oct 16 16:25:14 UTC 2017

So, the parent folder (“i4udq-q2yx2”) is definitely in sync.

That file in the output is pretty huge - ~28GB.

What if the new backup (on the source host) has been started and removed the folder “Backup 2017-10-14 223007” before the file sync has been completed? What error message should be in this case?

AudriusButkevicius · October 16, 2017, 4:57pm

If you are talking about on disk folders rather than syncthing folders then it should have been something about peers having this file going away (as there is nowhere to find this file), if you are talking about syncthing folders, and you are cycling them via some automated method, then this is understandable, as you remove syncthing folders for which requests might already be in flight

jazzl0ver · October 17, 2017, 2:46pm

Looks like I was unclear - I apologies. The source (filer-1) shares the folder /zmir/backup with st01 (/backup/filer-1). The sysstates and underneath subfolders are not shared separately.

AudriusButkevicius · October 17, 2017, 4:27pm

Do you have any kind of automation attached to syncthing?

jazzl0ver · October 17, 2017, 4:44pm

Not sure I understand what you mean by “automation”. The only couple things I have are

a daily cronjob which retrieves the Syncthing errors using curl and sends out an email alarm (GET from localhost:8384/rest/system/error).
nightly cronjob which stops and starts syncing (POST to localhost:8384/rest/system/config) to avoid synchronization while the nightly backups are running on the source host

AudriusButkevicius · October 17, 2017, 4:57pm

What do you mean by stops syncthing via config? How exactly are you stopping it?

jazzl0ver · October 17, 2017, 4:58pm

#-- pause syncthing during backups
0 1 * * * /usr/bin/curl -s -H X-API-Key:skip -X GET 'http://localhost:8384/rest/system/config' | /usr/bin/jq '.folders[].paused=true' | /usr/bin/curl -s -H X-API-Key:skip -X POST 'http://localhost:8384/rest/system/config' -d @- --header "Content-Type: application/json"

AudriusButkevicius · October 17, 2017, 5:05pm

I suspect this is the cause of it, as this pauses the folder, at which point it becomes unshared with the device, but there are still requests for it in flight if the data recently changed. Better option would be to kill syncthing at that point.