Shared Folder 'Out of Sync' and Other Issues

[Moisie]

Hi Simon:

@imsodin

Not calmh here, but I apparently didn’t understand what you wanted to do when pinging him, so chiming in all the same again

And I’m very grateful for you doing so!

@imsodin

Going back to 0.14.41 will (most likely) bring back the too many open files issue, as it is only fixed in 0.14.44(-rc.X).

As far as I understand currently syncing is happening on NAS01, so I don’t see the need to downgrade?

I appreciate the too many open files issue will return through downgrading - but my rationale was: all through the debugging process whilst running of 0.14.41, there wasn’t a problem with this. Perhaps something else in the change from 0.14.41 → 0.14.44 has broken it - and this would be a quick’n’easy way to check (subject to downgrade compatibility).

@imsodin

There is still a big chance that once NAS01 went trough one pull iteration (that didn’t happen yet I assume?), syncing/status indication will become smooth(er).

Ok. The first sync has (I believe) nearly finished - NAS01 says it’s only 29GB out now, but it’s doing a rescan due to a power cut over the weekend. I expect the scan will finish later today / some time tomorrow, so I’ll report back with news then.

Best wishes,

Pants.

[Moisie]

Hello:

NAS01 has finished scanning - but the syncing doesn’t seem to be progressing any further, with 28.1GB remaining.

There was a huge bunch of activity a short while ago, mainly of this form:

[GSXHK] 2018/01/18 13:05:45.629744 rwfolder.go:985: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201fc240 taking shortcut on file/path/1/here
[GSXHK] 2018/01/18 13:05:45.629937 verboseservice.go:48: VERBOSE: Started syncing "bvkmk-*****" / "file/path/1/here" (metadata file)
[GSXHK] 2018/01/18 13:05:45.630131 verboseservice.go:48: VERBOSE: Finished syncing "bvkmk-*****" / "file/path/1/here" (metadata file): Success

…but the display of out of sync items didn’t seem to count down as a result of this. Looking back through the log, I can’t see any instances of ‘update file’ for the last week now.

I also got a bunch of these during the flurry of activity:

[GSXHK] 2018/01/23 09:26:00.464048 verboseservice.go:48: VERBOSE: Remote change detected in folder "bvkmk-*****": added file file/path/2/here

…And then the output has ended here (for now):

[GSXHK] 2018/01/23 09:26:00.464103 rwfolder.go:271: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201fa240 changed 7047
[GSXHK] 2018/01/23 09:26:00.464138 rwfolder.go:294: INFO: Folder "NAS" (bvkmk-*****) isn't making progress. Pausing puller for 1h4m0s.
[GSXHK] 2018/01/23 09:26:00.464162 rwfolder.go:295: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201fa240 next pull in 1h4m0s
[GSXHK] 2018/01/23 09:26:00.464241 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now idle
[GSXHK] 2018/01/23 09:26:53.157615 progressemitter.go:240: DEBUG: progress emitter: bytes completed for bvkmk-*****: 0
[GSXHK] 2018/01/23 09:26:53.157678 model.go:716: DEBUG: model@0xc4201f8a20 NeedSize("bvkmk-*****"): {7047 0 0 0 30147155827 0 []}
[GSXHK] 2018/01/23 09:26:53.158471 verboseservice.go:48: VERBOSE: Summary for folder "bvkmk-*****" is map[localSymlinks:14048 inSyncFiles:5301600 needFiles:7047 state:idle sequence:67955805 globalDirectories:1039782 version:67955805 localFiles:5308647 needBytes:30147155827 localBytes:49148237489320 localDirectories:1039782 needSymlinks:0 globalBytes:49148237489320 globalDeleted:1555146 needDirectories:0 inSyncBytes:49118090333493 localDeleted:1555146 globalFiles:5308647 needDeletes:0 globalSymlinks:14048]
[GSXHK] 2018/01/23 09:34:55.462502 model.go:651: DEBUG: model@0xc4201f8a20 Completion(OVPYXBH-*******-*******-*******-*******-*******-*******-*******, "bvkmk-*****"): 73.529435 (13009816356896 / 49148237489320 = 0.264706)
[GSXHK] 2018/01/23 09:34:55.463097 verboseservice.go:48: VERBOSE: Completion for folder "bvkmk-*****" on device OVPYXBH-*******-*******-*******-*******-*******-*******-******* is 73.52943458099986%

Does any of this suggest anything useful?!

Many thanks,

Pants.

[AudriusButkevicius]

Folder "NAS" (bvkmk-*****) isn't making progress. Pausing puller for 1h4m0s.

It’s not doing anything. Look for errors in the logs and the UI.

I suspect permission problems.

[Moisie]

Hello:

Just in case it’s useful:

[GSXHK] 2018/01/23 10:30:00.493227 rwfolder.go:256: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201fa240 pulling (ignoresChanged=true)
[GSXHK] 2018/01/23 10:30:00.493547 rwfolder.go:327: DEBUG: sendReceiveFolder/bvkmk-*****@0xc4201fa240 c 2 p 64
[GSXHK] 2018/01/23 10:30:00.493683 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now syncing

…And another big flurry of remote changes detected and metadata files updated. Then the flurry ends with:

[GSXHK] 2018/01/23 10:55:53.841352 verboseservice.go:48: VERBOSE: Folder "bvkmk-*****" is now idle
[GSXHK] 2018/01/23 10:56:08.211759 model.go:1331: DEBUG: model@0xc4201f8a20 REQ(in): OVPYXBH-*******-*******-*******-*******-*******-*******-*******: "bvkmk-*****" / "file/path/1/.DS_Store" o=0 s=6148 t=false
[GSXHK] 2018/01/23 10:56:46.382286 progressemitter.go:240: DEBUG: progress emitter: bytes completed for bvkmk-*****: 0
[GSXHK] 2018/01/23 10:56:46.382364 model.go:716: DEBUG: model@0xc4201f8a20 NeedSize("bvkmk-*****"): {7047 0 0 0 30147155827 0 []}
[GSXHK] 2018/01/23 10:56:46.382933 verboseservice.go:48: VERBOSE: Summary for folder "bvkmk-*****" is map[version:67955805 globalFiles:5308647 globalBytes:49148237489320 globalDirectories:1039782 globalSymlinks:14048 localFiles:5308647 localSymlinks:14048 localBytes:49148237489320 needDeletes:0 inSyncBytes:49118090333493 globalDeleted:1555146 needBytes:30147155827 inSyncFiles:5301600 sequence:67955805 needFiles:7047 needDirectories:0 localDirectories:1039782 needSymlinks:0 state:idle localDeleted:1555146]

The entry at 10:56:08.211759 was in response to NAS02, which suddenly woke up and asked for the same file as earlier in the thread: Shared Folder 'Out of Sync' and Other Issues

The number of files (and size) of the Out of Sync Items isn’t going down - but every time I open the view on this, I’m seeing different files listed in the first page (and the same number of pages available to view each time).

Whilst all this is going on on NAS01, I’m not seeing anything interesting happening on NAS02 (just periodic NAT port remapping and listen address resolution changes, and badgering NAS01 for file/path/1/.DS_Store).

It’s not doing anything. Look for errors in the logs and the UI.

No errors reported on the UI - and obviously a huge bunch of stuff in the logs at the moment (model trace is currently enabled).

I suspect permission problems.

There shouldn’t be any issues here - the syncthing group has R/W permission over the entire shared folder, and Ignore Permissions is enabled (on both ends).

Thanks,

Pants.

[AudriusButkevicius]

You should disable verbose/debug logging and just post the whole log, as this spoon feeding is getting us nowhere, as I suspect you are missing the relevant messages among the verbose debugging cruft.

[imsodin (Simon)]

@Moisie

The number of files (and size) of the Out of Sync Items isn’t going down - but every time I open the view on this, I’m seeing different files listed in the first page (and the same number of pages available to view each time).

Whilst all this is going on on NAS01, I’m not seeing anything interesting happening on NAS02 (just periodic NAT port remapping and listen address resolution changes, and badgering NAS01 for file/path/1/.DS_Store).

I assume resource usage on NAS01 is high? I believe it is still reconciling “internal” conflicts. I call them “internal” because they are treated like conflicts, because both devices independently found the files, but as there is no actual difference there are no conflict copies (that’s probably the “metadata file” in one log). That should however finish in a single pull.

You could grep the log for "INFO:.* Puller (folder " to see what errors were encountered before (as there are none anymore in the GUI). Maybe there is a clue there. We should probably expand that logging line to “Puller error (folder…” to make it easier to search.

@AudriusButkevicius

You should disable verbose/debug logging and just post the whole log, as this spoon feeding is getting us nowhere, as I suspect you are missing the relevant messages among the verbose debugging cruft.

The problem is that the logs contain sensitive data and are huge anyway, that’s why it was previously uploaded to calmh’s FTP (and he seems to be a bit occupied with non-Syncthing life at the moment )

[Moisie]

Hello:

Many thanks for your input - much appreciated.

@imsodin

I assume resource usage on NAS01 is high?

Currently running at 8% - so not maxing out at all!

@imsodin

That should however finish in a single pull.

The data set is hardly changing at the moment - and it’s had nearly two weeks on the 0.14.44 build to settle down.

@imsodin

You could grep the log for "INFO:.* Puller (folder " to see what errors were encountered before (as there are none anymore in the GUI).

I searched for puller (folder - with no results found.

@AudriusButkevicius

You should disable verbose/debug logging and just post the whole log, as this spoon feeding is getting us nowhere, as I suspect you are missing the relevant messages among the verbose debugging cruft.

@imsodin

The problem is that the logs contain sensitive data and are huge anyway, that’s why it was previously uploaded to calmh’s FTP (and he seems to be a bit occupied with non-Syncthing life at the moment )

I’m happy to post the full logs to a Google Drive link for you both to look at, if that would be helpful. Which makes me think: Feature Request to obfuscate personal data from logs - would that be worthwhile?

As always, thanks for looking at this!

Best wishes,

Pants.

[Moisie]

Hello:

I think I have some good news: I haven’t touched the installation but, since my last update, NAS02 seems to now be pulling files and recognises that it’s 88000 files out of sync.

The Global States still don’t match between the units, but hopefully this is something which will now just work itself out.

Many many many thanks for your input - I really appreciate it, and feel guilty that I might have wasted your time and attention!

Best wishes,

Pants.

[imsodin (Simon)]

Great news! No need to feel guilty at all, it’s not like you force anyone to invest time and time invested on your reports definitely wasn’t wasted - the sparse too many files issue calmh uncovered with your logs was nasty. So quite the contrary, having users like you that go through lengthy debugging and provide necessary information are valuable to the project - thanks a lot!

[Moisie]

It’s a pleasure to be able to contribute something, even if I don’t have the skills to find my way around the codebase

But sitting here watching a tail of the log files from both systems rush past is bringing me sooo much joy, I can’t tell you!!