Out of sync items are incorrect and not syncing

Hi there

I have a PC running Windows 10 and a Synology NAS. Both with Syncthing 0.14.43-rc.1.

I used to have all files in sync. I moved the hard drive from one PC onto the new Windows 10 PC.

I can see, I think, that newer files since the move are syncing correctly, which is good. However, I have 117008 (43.4GiB) items out of sync. See here https://i.imgur.com/rgaSONM.png

I’ve looked in the forums and can see this topic mentioned right back to 2015, but can see the topics don’t get resolved - first topic points to the next one, the next one is getting somewhere but bottom says “moving this to a new topic” which isn’t linked, and then others that are commented but not resolved and then closed.

When I click on the items, the file list changes each time (despite choosing Newest First and the total number of un-sync’d items always being the same number) and they all say “Sync”

Oh and remote device says “Up to date”

So something’s awry somewhere. Firstly, the data on screen doesn’t match, and secondly the files left to sync are not progressing.

How can I debug this and move forward?

Thanks in advance

Everything looks ok to me. Syncthing is still receiving the list of files that need syncing from the remote peer, and it should be syncing them as displayed in the folder status.

The remote device is up to date as from this devices perspective, the remote device has all of the latest files (and is supplying them back to you).

What on screen data does not match? Local state numbers being equal to global ones doesn’t mean there is nothing out of sync (modifications).
Just to clarify: The syncing percentage and number of out of sync items does not decrease in time? That would be bad indeed (as in they should then show up as failed items) - check the logs, which you can now also do in the web UI by going to Actions -> Logs :smiley:

Hi Simon

Just a quick reply before I check logs … sure, not clear re “data on screen” - I meant that oe part says thousands of files out of sync, and the other part says “Up to date”.

And Audrius - sure, the sync has recognised that there are thousands of files to sync, but that same number and GiB to sync has been like that for 2+ weeks.

Will go check logs now and post back some more.

OK, one more from me. I can see log entries on the Windows PC as follows, but nothing to do with file syncing - should I enable some specific logging?

2018-01-04 11:09:55 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on Loopback Pseudo-Interface 1
2018-01-04 11:09:55 Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on Loopback Pseudo-Interface 1
2018-01-04 11:09:55 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on Loopback Pseudo-Interface 1
2018-01-04 11:09:55 Discovered gateway at 172.31.1.254
2018-01-04 11:10:05 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on Ethernet finished.
2018-01-04 11:10:05 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on Ethernet finished.
2018-01-04 11:10:05 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on Loopback Pseudo-Interface 1 finished.
2018-01-04 11:10:05 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on Loopback Pseudo-Interface 1 finished.
2018-01-04 11:10:05 Timeout trying to get external address, assume no NAT-PMP available

Thanks

You can enable model logging and see what happens.

I might be a little premature, but this is what I’m seeing:

2018-01-04 12:01:14 Enabled debug data for "model"
2018-01-04 12:01:16 Disabled debug data for "nat"
2018-01-04 12:01:16 Disabled debug data for "pmp"
2018-01-04 12:01:19 Disabled debug data for "upnp"
2018-01-04 12:01:39 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:01:40 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 1m1.440549812s
2018-01-04 12:01:41 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:01:41 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 49.333052355s
2018-01-04 12:02:05 &{60000000000 0xc0450f6100 0xc042124120 0xc042124180} next rescan in 53.444342631s
2018-01-04 12:02:30 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:02:30 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 51.57363536s
2018-01-04 12:02:42 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:02:42 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 54.904746711s
2018-01-04 12:02:58 sendReceiveFolder/tcp7k-dhkkq@0xc0421ac480 Scanning subdirectories
2018-01-04 12:03:22 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:03:22 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 1m9.46750738s
2018-01-04 12:03:37 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:03:38 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 52.126024926s
2018-01-04 12:04:01 &{60000000000 0xc0450f6100 0xc042124120 0xc042124180} next rescan in 49.577738503s
2018-01-04 12:04:30 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:04:31 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 1m2.657040659s
2018-01-04 12:04:31 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:04:31 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 50.776726167s
2018-01-04 12:04:50 sendReceiveFolder/tcp7k-dhkkq@0xc0421ac480 Scanning subdirectories
2018-01-04 12:05:22 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:05:22 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 1m2.121287381s
2018-01-04 12:05:34 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:05:35 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 54.032633756s
2018-01-04 12:05:52 &{60000000000 0xc0450f6100 0xc042124120 0xc042124180} next rescan in 48.40924693s
2018-01-04 12:06:24 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:06:24 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 1m6.17256561s
2018-01-04 12:06:29 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:06:30 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 55.449894595s
2018-01-04 12:06:41 sendReceiveFolder/tcp7k-dhkkq@0xc0421ac480 Scanning subdirectories
2018-01-04 12:07:25 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:07:26 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 54.86007221s
2018-01-04 12:07:31 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:07:31 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 50.881970974s
2018-01-04 12:07:43 &{60000000000 0xc0450f6100 0xc042124120 0xc042124180} next rescan in 1m2.216410795s
2018-01-04 12:08:21 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:08:21 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:08:21 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 56.668112662s
2018-01-04 12:08:22 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 46.323786737s
2018-01-04 12:08:45 sendReceiveFolder/tcp7k-dhkkq@0xc0421ac480 Scanning subdirectories
2018-01-04 12:09:08 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:09:09 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 1m2.16134064s
2018-01-04 12:09:18 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:09:18 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 1m1.58721447s
2018-01-04 12:09:47 &{60000000000 0xc0450f6100 0xc042124120 0xc042124180} next rescan in 52.751911583s
2018-01-04 12:10:11 sendReceiveFolder/Sage@0xc0421ac900 Scanning subdirectories
2018-01-04 12:10:12 &{60000000000 0xc0431de340 0xc042279620 0xc042279680} next rescan in 1m8.731332319s
2018-01-04 12:10:20 sendReceiveFolder/default@0xc0421ac6c0 Scanning subdirectories
2018-01-04 12:10:20 &{60000000000 0xc04364fc40 0xc043754420 0xc043754480} next rescan in 46.712670518s

It doesn’t seem it’s downloading anything. Looks like the model service is dead. Do you have auto accept enabled somewhere?

Hi Audrius

Thanks for your continued replies … how would I check that, please? I’m an IT guy (own a web company) but not a Syncthing guy! :slight_smile:

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.

2 Likes

Yeah, this sucks UX wise, we should fix it.

1 Like

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 :slight_smile: