Problems using Syncthing on Synology

alh · December 3, 2018, 3:33pm

I have currently two organisations using Syncthing on Synology and we wanted to start using the FS watcher but get stuck somehow:

We see complaints about paths not being accessible in the WebGUI but their permissions don’t differ from other files/dirs that work fine. Error message: “error while traversing /volume1/…: permission denied” (permissions are 100% fine).
In the logs we find the following error message which I fail to interpret "2018-12-03 08:49:03 wrapper.go:504 basic /volume1/@appstore/syncthing/var Usage . {1934024757248 7672030584832} ".

Any pointers would be great! Thanks a lot.

imsodin · December 3, 2018, 3:43pm

Which Syncthing version?

For dot one, check the permissions of all files (also hidden) directly in the directory where the error occurs.

Second dot: That’s just a normal filesystem debug message - apparently you have the fs facility enabled. In any case it’s not an error.

alh · December 3, 2018, 3:52pm

I tried that. I check using ls -la and synoacltool -get /path/to/:

NAS 1: only one file in the folder, permissions are fine
NAS 2: many files but in my opinion permissions are fine as well

On both systems the ACLs are set as follows: “group:sc-syncthing:allow:rwxpdDaARWc–:----”

I will try to restart Syncthing…

alh · December 3, 2018, 5:02pm

I restarted Syncthing, same error, nothing in the log…

DavC · December 3, 2018, 5:25pm

Same error ! Syncthing v0.14.52, Linux (64 bit) DSM 6.2-23739 Update 2

AudriusButkevicius · December 3, 2018, 6:12pm

Search existing synology related threads on this forum and syncthing related threads on synology forum. I am pretty sure I’ve seen this issue before not that long ago.

alh · December 3, 2018, 11:14pm

So far no luck searching…

AudriusButkevicius · December 3, 2018, 11:40pm

https://forum.syncthing.net/search?q=Synology%20permission%20order%3Alatest_topic

AudriusButkevicius · December 3, 2018, 11:41pm

Also the usage stuff does not look like an error, failing to watch might just be an incompatible kernel.

alh · December 4, 2018, 7:07am

I think I’m able to search a forum… but there is nothing that corresponds.

My system and kernel:
Linux SERVERNAME 3.10.105 #23824 SMP Fri Oct 12 18:30:21 CST 2018 x86_64 GNU/Linux synology_avoton_1517+

As said before: permissions are identical to other files/dirs that don’t throw any errors.

alh · December 5, 2018, 8:29pm

Is there anything I can do to gather more information that helps finding the cause for this?

AudriusButkevicius · December 5, 2018, 8:38pm

Is it just watching that does not work, or scanning in general?

alh · December 5, 2018, 10:06pm

Scanning works just fine. But I read somewhere on the forum here that it would fail silently on non-accessible files, contrary to watching which would throw an error. In this case however, the two machines syncing report different paths that fail for watching. Also I don’t see any files missing…

AudriusButkevicius · December 5, 2018, 10:20pm

Well if the files counts match then it was able to scan everything. You can run syncthing under strace and filter syscalls returning EPERM (or whatever the error name is in linux) and see which one fails. I suspect it will be the inotify syscall on /volume/ because its some fancy filesystem that does not support inotify. I suspect if you point it at some other directory in /home/ etc it will work. Or perhaps /volume/ is a symlink or hardlink, which cannot be watched.

alh · December 5, 2018, 10:40pm

File counts match and always have…

FS is BTRFS and Synology uses a modified version of inotify. Also no hard or soft links involved:

stat /volume1
  File: ‘/volume1’
  Size: 276       	Blocks: 0          IO Block: 4096   directory
Device: 1dh/29d	Inode: 256         Links: 1
Access: (0755/drwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-01-19 11:30:17.284875237 +0100
Modify: 2018-12-03 19:57:48.387169200 +0100
Change: 2018-12-05 23:01:55.224788588 +0100
 Birth: -

stat /volume1/KUNDEN_1/
  File: ‘/volume1/KUNDEN_1/’
  Size: 604       	Blocks: 0          IO Block: 4096   directory
Device: 20h/32d	Inode: 256         Links: 1
Access: (0000/d---------)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-12-05 14:42:18.479871951 +0100
Modify: 2018-12-05 14:42:18.479871951 +0100
Change: 2018-12-05 14:42:18.479871951 +0100
 Birth: -

stat /volume1/KUNDEN_1/_Schriften_für_alle/
  File: ‘/volume1/KUNDEN_1/_Schriften_für_alle/’
  Size: 826       	Blocks: 0          IO Block: 4096   directory
Device: 20h/32d	Inode: 806492      Links: 1
Access: (0000/d---------)  Uid: ( 1026/  sadmin)   Gid: (  100/   users)
Access: 2018-02-27 09:50:08.000000000 +0100
Modify: 2018-02-27 09:50:08.000000000 +0100
Change: 2018-12-04 22:17:11.053217777 +0100
 Birth: -

I will try the strace…

AudriusButkevicius · December 5, 2018, 10:45pm

Also, one of the listed directories are owned by root, other is owned by sadmin, and it’s not clear where the folder root is.

alh · December 5, 2018, 11:43pm

I’m not sure I follow you… all permissions on Synology are managed via ACLs. I cannot meddle with the standard POSIX permissions.

The log with STTRACE does not provide more information to me:

2018-12-06 00:34:11 folder.go:611 basic /volume1/KUNDEN_1 Watch . Matcher/[$RECYCLE.BIN **/$RECYCLE.BIN $RECYCLE.BIN/** **/$RECYCLE.BIN/** $Recycle.Bin **/$Recycle.Bin $Recycle.Bin/** **/$Recycle.Bin/** (?d)lost+found (?d)**/lost+found (?d)lost+found/** (?d)**/lost+found/** (?d).DocumentRevisions-V100 (?d)**/.DocumentRevisions-V100 (?d).DocumentRevisions-V100/** (?d)**/.DocumentRevisions-V100/** (?d).TemporaryItems (?d)**/.TemporaryItems (?d).TemporaryItems/** (?d)**/.TemporaryItems/** (?d).fseventsd (?d)**/.fseventsd (?d).fseventsd/** (?d)**/.fseventsd/** (?d).iCloud (?d)**/.iCloud (?d).iCloud/** (?d)**/.iCloud/** (?d).DS_Store (?d)**/.DS_Store (?d).DS_Store/** (?d)**/.DS_Store/** (?d).Spotlight-V100 (?d)**/.Spotlight-V100 (?d).Spotlight-V100/** (?d)**/.Spotlight-V100/** (?d).Trashes (?d)**/.Trashes (?d).Trashes/** (?d)**/.Trashes/** .Trash-* **/.Trash-* .Trash-*/** **/.Trash-*/** ehthumbs.db **/ehthumbs.db ehthumbs.db/** **/ehthumbs.db/** (?d)desktop.ini (?d)**/desktop.ini (?d)desktop.ini/** (?d)**/desktop.ini/** (?d)Thumbs.db (?d)**/Thumbs.db (?d)Thumbs.db/** (?d)**/Thumbs.db/** (?d)~* (?d)**/~* (?d)~*/** (?d)**/~*/** *~ **/*~ *~/** **/*~/** .~lock.* **/.~lock.* .~lock.*/** **/.~lock.*/** *.part **/*.part *.part/** **/*.part/** *.filepart **/*.filepart *.filepart/** **/*.filepart/** .csync_journal.db **/.csync_journal.db .csync_journal.db/** **/.csync_journal.db/** .csync_journal.db.tmp **/.csync_journal.db.tmp .csync_journal.db.tmp/** **/.csync_journal.db.tmp/** *.swn **/*.swn *.swn/** **/*.swn/** *.swp **/*.swp *.swp/** **/*.swp/** *.swo **/*.swo *.swo/** **/*.swo/** .dropbox **/.dropbox .dropbox/** **/.dropbox/** .dropbox.attr **/.dropbox.attr .dropbox.attr/** **/.dropbox.attr/** *.crdownload **/*.crdownload *.crdownload/** **/*.crdownload/** (?d)@eaDir (?d)**/@eaDir (?d)@eaDir/** (?d)**/@eaDir/** @SynoResource **/@SynoResource @SynoResource/** **/@SynoResource/** .@__thumb **/.@__thumb .@__thumb/** **/.@__thumb/** .thumbnails **/.thumbnails .thumbnails/** **/.thumbnails/** ._* **/._* ._*/** **/._*/** #snapshot **/#snapshot #snapshot/** **/#snapshot/** (?d)node_modules (?d)**/node_modules (?d)node_modules/** (?d)**/node_modules/** #recycle **/#recycle #recycle/** **/#recycle/** /Autofleetcontrol /Autofleetcontrol/** /DCBK /DCBK/** /GRUNDLAGEN?WBT /GRUNDLAGEN?WBT/** /Grasdorf /Grasdorf/** /KunstAkademie_Foerderverein /KunstAkademie_Foerderverein/**]@0xc0002481b0 true error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied
2018-12-06 00:34:11 log 69 FolderWatchStateChanged map[folder:my-folder-id from:error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied to:error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied]
2018-12-06 00:34:11 Repeat error while trying to start filesystem watcher for folder "DCBK_SALT_KUNDEN_1" (my-folder-id), trying again in 1min: error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied
2018-12-06 00:34:11 http: GET "/rest/events?since=68": status 200, 380 bytes in 59050.45 ms
2018-12-06 00:34:12 my-folder-id WithNeedTruncated(7777777-777777N-7777777-777777N-7777777-777777N-7777777-77777Q4)
2018-12-06 00:34:12 progress emitter: bytes completed for my-folder-id: 0
2018-12-06 00:34:12 model@0xc00002e2c0 NeedSize("my-folder-id"): {0 0 0 0 0 0 [] 0}
2018-12-06 00:34:12 folderconfiguration.go:151 basic /volume1/KUNDEN_1 Stat . {0xc005aff520} <nil>
2018-12-06 00:34:12 folderconfiguration.go:169 basic /volume1/KUNDEN_1 Stat .stfolder {0xc005aff5f0} <nil>
2018-12-06 00:34:12 ignore.go:544 basic /volume1/KUNDEN_1 Stat .stignore {0xc005aff6c0} <nil>
2018-12-06 00:34:12 log 70 FolderSummary map[folder:my-folder-id summary:map[watchError:error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied globalBytes:2355058942912 localDeleted:35807 needSymlinks:0 needDeletes:0 inSyncBytes:2355058942912 ignorePatterns:true errors:0 pullErrors:0 invalid: globalDirectories:40099 localDirectories:40099 stateChanged:2018-12-06 00:26:35.391486179 +0100 CET m=+474.192771854 version:923442 globalFiles:215233 globalDeleted:35829 localSymlinks:6 localBytes:2355058942912 needFiles:0 state:idle globalSymlinks:6 localFiles:215233 needDirectories:0 needBytes:0 inSyncFiles:215233 sequence:923442]]
2018-12-06 00:34:12 stats.DeviceStatisticsReference.WasSeen: REMOTE-NAS-ID
2018-12-06 00:34:12 http: GET "/rest/events?since=69": status 200, 1080 bytes in 1063.83 ms
2018-12-06 00:34:12 my-folder-id WithNeedTruncated(REMOTE-NAS-ID)
2018-12-06 00:34:13 model@0xc00002e2c0 Completion(REMOTE-NAS-ID, "my-folder-id"): 100.000000 (0 / 2355058942912 = 0.000000)
2018-12-06 00:34:13 log 71 FolderCompletion map[device:REMOTE-NAS-ID completion:100 needBytes:0 needItems:0 globalBytes:2355058942912 needDeletes:0 folder:my-folder-id]

alh · December 5, 2018, 11:49pm

Sorry wrong strace

I guess I need some sleep…

alh · December 6, 2018, 12:20am

The output of strace, nothing imho:

futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL[2H2JG] 01:03:51 INFO: syncthing v0.14.54 "Dysprosium Dragonfly" (go1.11.1 linux-amd64) teamcity@build.syncthing.net 2018-12-05 11:18:45 UTC
[2H2JG] 01:03:51 INFO: My ID: LOCAL-NAS-ID
[2H2JG] 01:03:52 INFO: Single thread SHA256 performance is 93 MB/s using minio/sha256-simd (68 MB/s using crypto/sha256).
[2H2JG] 01:03:53 INFO: Hashing performance is 80.95 MB/s
[2H2JG] 01:03:53 INFO: Ready to synchronize "SYNC_FOLDER_NAME" (folder-id) (sendreceive)
[2H2JG] 01:03:53 INFO: Overall send rate is unlimited, receive rate is unlimited
[2H2JG] 01:03:53 INFO: TCP listener ([::]:22000) starting
[2H2JG] 01:03:53 INFO: Device LOCAL-NAS-ID is "Local-NAS" at [dynamic]
[2H2JG] 01:03:53 INFO: Device REMOTE-NAS-ID is "Remote-NAS" at [tcp://172.16.1.11]
[2H2JG] 01:03:53 INFO: GUI and API listening on [::]:8384
[2H2JG] 01:03:53 INFO: Access the GUI via the following URL: https://127.0.0.1:8384/
[2H2JG] 01:03:54 INFO: Established secure connection to REMOTE-NAS-ID at 192.168.1.11:37711-172.16.1.11:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384)
[2H2JG] 01:03:54 INFO: Device REMOTE-NAS-ID client is "syncthing v0.14.54" named "Remote-NAS" at 192.168.1.11:37711-172.16.1.11:22000/tcp-client
) = 0
epoll_pwait(4, {}, 128, 0, NULL)        = 0
futex(0x131b0d0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00004e4c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x131b4c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL[2H2JG] 01:06:35 INFO: Completed initial scan of sendreceive folder "SYNC_FOLDER_NAME" (folder-id)
) = 0
futex(0xc00006c140, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x131b4c8, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0xc00006d2c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00004ebc0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006c140, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006d2c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131aff0, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_pwait(4, {}, 128, 0, NULL)        = 0
futex(0x131b0d0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006c140, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
epoll_pwait(4, {}, 128, 0, NULL)        = 0
futex(0x131b0d0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006c140, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006d2c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00006c140, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00004ebc0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131aff0, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_pwait(4, {}, 128, 0, NULL)        = 0
futex(0x131b0d0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131aff0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xc00004ebc0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL[2H2JG] 2018/12/06 01:14:14.211931 gui.go:637: INFO: Enabled debug data for "watchaggregator"
) = 0
futex(0x131b0c0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x131aff0, FUTEX_WAKE_PRIVATE, 1) = 1
sched_yield()                           = 0
futex(0x131aff0, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
futex(0x131bba0, FUTEX_WAIT_PRIVATE, 0, NULL[2H2JG] 2018/12/06 01:14:53.190827 gui.go:637: INFO: Enabled debug data for "model"
[2H2JG] 2018/12/06 01:14:54.625512 gui.go:637: INFO: Enabled debug data for "walkfs"
[2H2JG] 2018/12/06 01:14:55.766033 gui.go:637: INFO: Enabled debug data for "fs"
[2H2JG] 2018/12/06 01:14:57.395562 folder.go:632: DEBUG: Repeat error while trying to start filesystem watcher for folder "SYNC_FOLDER_NAME" (folder-id), trying again in 1min: error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied
[2H2JG] 2018/12/06 01:14:59.051113 progressemitter.go:240: DEBUG: progress emitter: bytes completed for folder-id: 0
[2H2JG] 2018/12/06 01:14:59.051208 model.go:739: DEBUG: model@0xc000116160 NeedSize("folder-id"): {0 0 0 0 0 0 [] 0}
[2H2JG] 2018/12/06 01:15:00.216812 model.go:662: DEBUG: model@0xc000116160 Completion(REMOTE-NAS-ID, "folder-id"): 100.000000 (0 / 2355058942912 = 0.000000)
[2H2JG] 2018/12/06 01:15:57.614770 folder.go:632: DEBUG: Repeat error while trying to start filesystem watcher for folder "SYNC_FOLDER_NAME" (folder-id), trying again in 1min: error while traversing /volume1/KUNDEN_1/_Schriften_für_alle: permission denied
[2H2JG] 2018/12/06 01:15:58.552956 progressemitter.go:240: DEBUG: progress emitter: bytes completed for folder-id: 0
[2H2JG] 2018/12/06 01:15:58.553019 model.go:739: DEBUG: model@0xc000116160 NeedSize("folder-id"): {0 0 0 0 0 0 [] 0}
[2H2JG] 2018/12/06 01:15:59.754413 model.go:662: DEBUG: model@0xc000116160 Completion(REMOTE-NAS-ID, "folder-id"): 100.000000 (0 / 2355058942912 = 0.000000)
) = 0

alh · December 6, 2018, 12:53am

There are no inotify watches set by syncthing. The number hovers around 20. Maybe it is a problem with the implementation done by SynoCommunity. I will try using entware-ng’s tomorrow.