It’s in the advanced settings menu, but if you don’t know about it’s unlikely that’s the cause. Can you restart with STTRACE=model env var and provide the log from stdout after a few minutes and report if it still shows up after restart?
Also, does the device look like it’s out of sync on the remote end?
@calmh this could be your metadata cache issue right?
Could be. You can set STDBCHECKEVERY=0 to wipe out the cache and recalculate at startup, essentially restoring the old behavior. To check.
Hi guys
So I’ve set the STTRACE model and the STDBCHECKEVERY env variables and restarted syncthing on the PC (don’t know how to do this on the Synology NAS, so thought I’d try just this first).
This is the stuff i’m seeing:
2018-01-04 15:29:16 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:29:16 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 53.871160267s
2018-01-04 15:29:38 model@0xc04219e360 IDXUP(in): DFXNXN3-WY2XTYG-UZP6O7B-CAOJCGM-FHZJ52E-6SYBYFV-W56QLBY-SS6A4A6 / "tcp7k-dhkkq": 2 files
2018-01-04 15:29:38 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 pulling (ignoresChanged=false)
2018-01-04 15:29:38 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 c 2 p 64
2018-01-04 15:29:39 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 changed 0
2018-01-04 15:29:40 progress emitter: bytes completed for tcp7k-dhkkq: 0
2018-01-04 15:29:40 model@0xc04219e360 NeedSize("tcp7k-dhkkq"): {0 0 0 0 0 0 []}
2018-01-04 15:29:42 model@0xc04219e360 Completion(DFXNXN3-WY2XTYG-UZP6O7B-CAOJCGM-FHZJ52E-6SYBYFV-W56QLBY-SS6A4A6, "tcp7k-dhkkq"): 90.269790 (46527856687 / 478179359557 = 0.097302)
2018-01-04 15:30:03 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:30:03 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 47.380147576s
2018-01-04 15:30:09 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:30:09 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 46.357303002s
2018-01-04 15:30:14 Sent usage report (version 3)
2018-01-04 15:30:20 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 Scanning subdirectories
2018-01-04 15:30:51 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:30:52 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 1m7.509460321s
2018-01-04 15:30:56 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:30:56 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 58.981721337s
2018-01-04 15:31:22 &{60000000000 0xc043d92080 0xc042ae2840 0xc042ae28a0} next rescan in 1m2.883236728s
2018-01-04 15:31:55 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:31:55 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 45.390832774s
2018-01-04 15:31:59 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:32:00 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 1m0.349090574s
2018-01-04 15:32:25 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 Scanning subdirectories
2018-01-04 15:32:40 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:32:40 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 55.327582167s
2018-01-04 15:33:00 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:33:01 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 57.118014896s
2018-01-04 15:33:26 &{60000000000 0xc043d92080 0xc042ae2840 0xc042ae28a0} next rescan in 1m4.785675524s
2018-01-04 15:33:35 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:33:35 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 1m7.679960444s
2018-01-04 15:33:58 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:33:59 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 45.942168954s
2018-01-04 15:34:31 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 Scanning subdirectories
2018-01-04 15:34:43 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:34:43 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 51.348435777s
2018-01-04 15:34:45 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:34:46 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 45.869228277s
2018-01-04 15:35:32 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:35:32 &{60000000000 0xc043d92080 0xc042ae2840 0xc042ae28a0} next rescan in 55.814961257s
2018-01-04 15:35:33 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 1m9.672389484s
2018-01-04 15:35:35 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:35:35 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 49.046218202s
2018-01-04 15:36:24 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:36:24 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 59.534038224s
2018-01-04 15:36:28 sendReceiveFolder/tcp7k-dhkkq@0xc0421a0900 Scanning subdirectories
2018-01-04 15:36:42 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:36:43 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 1m2.333925938s
2018-01-04 15:37:23 sendReceiveFolder/default@0xc0421a06c0 Scanning subdirectories
2018-01-04 15:37:23 &{60000000000 0xc042033f40 0xc042ae25a0 0xc042ae2600} next rescan in 1m5.655531055s
2018-01-04 15:37:29 &{60000000000 0xc043d92080 0xc042ae2840 0xc042ae28a0} next rescan in 1m11.379749342s
2018-01-04 15:37:46 sendReceiveFolder/Sage@0xc0421a0b40 Scanning subdirectories
2018-01-04 15:37:47 &{60000000000 0xc043d92200 0xc042ae2ae0 0xc042ae2b40} next rescan in 53.698952533s
I also see a few entries for files that are new and changing right now on the PC side - I know the files are being worked on now, so are totally new. I didn’t post those as they contain quite a bit of confidential data.
Should I now remove that STDBCHECKEVERY environment variable? Do I also need to set these two variables on the NAS drive somehow for this to work?
Not sure if this has helped you both …
So, that’s from the other side compared to the screenshot you posted first? Seems consistent. The device that has the files out of sync should be the one to know why are they are not getting updated.
Yes that is from the other side.
OK … sorry, so what should I do next? Is there something I’ve done wrong? Or something wrong with the software? (in terms of the same number of files never showing as synced)
Open up the gui on the device where the files are out of sync. Wait at least a minute. Hopefully, under the “out of sync” line there will pop up another one with “failed items” that you can click on and get details on why they are not syncing.
@imsodin or is the pulling too seldom now for that to happen…? Hmm.
Or maybe pull up the logs on that one, like you did here, but without trace options and stuff. Looks for something like mentions the files in question and anything that sounds like an error.
@marky_uk You can pause and restart the folder, that will cause a pull and thus an error event and relevant model logging.
@calmh Pulls due to errors can happen as rarely as every 1h - so that can be an issue. I didn’t consider that the web UI is dependent on frequent error events - errors should probably be part of the folder summary and enter the UI that way.
Yeah, this sucks UX wise, we should fix it.
Hi there
Now I’m home (where the NAS is, for some reason I couldn’t access the GUI remotely all day) I’m seeing this, now I’ve enabled model logging, and then paused and restarted the sync folder -
2018-01-04 18:15:12 model@0xc4201fe360 NeedSize("Photos"): {0 0 0 0 0 0 []}
2018-01-04 18:15:20 progress emitter: bytes completed for tcp7k-dhkkq: 0
2018-01-04 18:15:20 model@0xc4201fe360 NeedSize("tcp7k-dhkkq"): {102849 14159 0 0 46527856687 0 []}
2018-01-04 18:15:20 progress emitter: bytes completed for Sage: 0
2018-01-04 18:15:20 model@0xc4201fe360 NeedSize("Sage"): {0 0 0 0 0 0 []}
2018-01-04 18:15:21 model@0xc4201fe360 Completion(ALYYWW6-OQAK5DM-XE5CH4E-EKP4LYC-BRZJSRK-DEZUEJQ-PREYUWO-LI54BQD, "Sage"): 100.000000 (0 / 821865014 = 0.000000)
2018-01-04 18:15:27 model@0xc4201fe360 Completion(ALYYWW6-OQAK5DM-XE5CH4E-EKP4LYC-BRZJSRK-DEZUEJQ-PREYUWO-LI54BQD, "tcp7k-dhkkq"): 100.000000 (0 / 478182952671 = 0.000000)
2018-01-04 18:15:30 model@0xc4201fe360 Completion(ZKUIGJ7-5SP6LRI-HX65KM7-THE3QWI-4JQCRT6-RXHEX5Q-33VKKIA-NBWTGAE, "Photos"): 95.000000 (0 / 807856409 = 0.000000)
2018-01-04 18:15:35 progress emitter: bytes completed for tcp7k-dhkkq: 0
2018-01-04 18:15:35 model@0xc4201fe360 NeedSize("tcp7k-dhkkq"): {102849 14159 0 0 46527856687 0 []}
Is that of use? I’m not sure what I should be looking for, and posting here.
Just to be sure: We need logs from the device where the folder is stuck syncing. What I would expect are “Folder label (id) isn’t making progress” messages. Or just post everything that comes up after pause/resume of the folder.
EDIT: Sorry, forgot to answer your explicit question: That log excerpt isn’t helpful unfortunately.
Hi Simon
Thank you. Sure.
Can I just ask something - just a hunch here - will Syncthing stop if there are too many errors?
I’m seeing this, as an example in the logs:
2018-01-04 18:32:20 sendReceiveFolder/tcp7k-dhkkq@0xc420200240 taking shortcut on WebWork/images/open-source-icons/GIF/brown/Thumbs.db
2018-01-04 18:32:20 Puller (folder "LogicSpot" (tcp7k-dhkkq), file "WebWork/images/open-source-icons/GIF/brown/Thumbs.db"): shortcut chmod: chmod /volume1/LogicSpot/WebWork/images/open-source-icons/GIF/brown/Thumbs.db: operation not permitted
There’s hundreds of them. Not sure why, as I set ownership of all folders under LogicSpot for the sc-syncthing user on the Synology NAS … but hey, that’s another problem if you could answer my question first 
The thumb files might be generated by the NAS OS itself, so they get generated under a different user. Syncthing does not sync ownership.
Also, your NAS might not support chmod and only support ACLs which would prevent any permissions modifications. There is an ignore permissions option under the folder for this type of situations.
Nope, never. That explains your problem: The out of sync files can’t be modified due to permission problems. As Audrius said, you can use ignore permissions or you can investigate the files from the log and solve the actual permission issue.
These files should however result in a failed items entry in the web UI. When you restart the folder, does no failed items row show up for this folder?
Simon - I am not seeing any failed items when I pause and resume the sync from the Synology drive.
I will try ignore permissions and see if that helps.
@calmh @imsodin so I am still confused.
Syncing state can only happen within the puller loop, which means this is where we are at. Syncthing state doesn’t last long in case of errors. New puller loop tries 3 times, if changed is non zero, and then emits errors. How do failed files affect “changed” variable in puller iteration? I assume it doesn’t and we exit after the first iteration, exiting the loop and not emitting the errors event?
Failed items do still increase changed, it essential means to be changed not has been successfully changed. However I agree I am confused now that you bring this up: During syncing errors are cleared in the web UI as at the end of syncing a new list of failed items will be incoming (or not). So does the folder in this case ever come out of the syncing state (it should…)?
@marky_uk Do you have any log entries containing “Pausing puller for” for that folder?
So, setting “ignore permissions” on both sides has solved the problem in entirety, and very quickly indeed. I think a rescan occurred on both, and I was then told all items are in sync! See here - https://i.imgur.com/4yvqNT6.png
Can I help any more in debugging this issue, by supplying logs directly to either of you, etc?
I’m happy it’s now working - just to reiterate my setup is a Windows 10 PC at one side, and Synology NAS drive at the other
Glad it works. It is still unclear to me why you did’t get a list of failed items after pausing and resuming the folder. If you still have access to the old logs, I would still be interested in whether there is/are lines(s) containing “Pausing puller for” after pausing and resuming the folder.
Hi Simon
I have the logs and more than happy to share what I have but would prefer to do so directly. How can I send this to you?
Mark
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.
