Out of sync items and mismatched file / folder counts


(Jnnewton) #1

I’ve been having issues with several computers not staying in sync. I have a setup where I have a central “server”, which is on all the time and always connected to the internet. I also have a desktop computer and a couple of laptops that I’m trying to keep in sync. I always have mismatched file counts and “Out of Sync Items”, but don’t show failed items on either side.

Here’s the Server folder (running 0.14.48, which is the latest available in FreeBSD ports):

And Here’s the view form my desktop (running 0.14.49, which is the latest I think to download for windows):

The desktop is definitely reporting thing number of local files and folders incorrectly, and that folder is listed on both sides when looking in Out of sync items:

How do I track down why this is out of sync and not making any progress (it’s been running all day.

EDIT: Had all these images nicely organized in the post, but can only post one, so here’s the whole lot in one:


#2

Global state doesn’t care about (local) ignores, so the difference between local and global is likely because of the ignores.

Ignores are case sensitive (if the fs is case sensitive), so your ignores have different effects on Windows, than on Linux.


(Jnnewton) #3

I don’t really want to get off on a tangent here, but the difference between local and global doesn’t bother me (i don’t really care what each means or doesn’t mean with regards to ignores). There are files that wouldn’t be ignored (such as mycode.c or mycode.h for this specific folder) regardless of the case sensitivity and they are not syncing, not showing failed. I just wanted to note that on the windows side, it thinks there’s 29 files, but there’s more like 2k (with or without ignores). Where do i see why /path/to/file is out of sync and not syncing? All i see is it’s been modified by some machine.

I would think that global would match globally (from machine to machine) though, regardless of whether it matches local. If it’s not supposed to, then I guess I don’t understand the meaning or labeling of global things.


(Audrius Butkevicius) #4

This definately looks like a bug. The question is how can we reproduce it to understand what’s happening.

I guess you could run syncthing -reset-deltas which should fix it, but it would be more interesting to know how it happened in the first place.


(Jnnewton) #5

I restarted the server as a service, after starting with syncthing -reset-deltas (which didn’t fix the issue). Then started it back up as a service.

Latest change on the server and desktop shows: Updated flash_drive.sync-conflict-20180728-12

Both UI’s show the other is Disconnected (but both show an IP address and Last seen is updated regularly, just barely trailing the current time. What is the difference between seen and connected. Does the last seen mean anything important, because initially I though it meant last connected, but it’s obviously seeing regularly while being “Disconnected” (Bug?)

Added a file called new_server_doc.txt on the server.

File is not picked up by the file watcher (Bug?), but is picked up by the timed rescan. File is synced over to desktop.

Desktop GUI updates latest change. Server does not (Bug?).

Are there any of those things that are me just misunderstanding, and if not, I can reproduce them, but don’t know enough about the codebase to tell anyone where to look.

As for the -reset-deltas didn’t fix anything when run on the server (mentioned above). I am going to try to figure out how to run it on my windows desktop or maybe one of my laptops.

Maybe a bit of information on the Disconnected info:

From the Desktop: Established secure connection to at An existing connection was forcibly closed by the remote host.

Repeats Over and Over again. Ok, why?

On the Server This repeats: 192.168.2.115:63172/tcp-server closed: protocol error: index: “”: filename not in canonical format

Which corresponds to this: https://github.com/syncthing/syncthing/issues/3913 Which is closed as legacy even though it affects later versions under some very specific cases. Have to figure out how to break the cycle.


(Audrius Butkevicius) #6

If they are not connecting, you won’t see the effect of reset-deltas. The connection error just says that the connection was terminated by the remote peer, so you should check the remote logs to see why the device decided to disconnect.


(Jnnewton) #7

curl -X POST -H "X-API-Key: abc123" http://localhost:8384/rest/system/reset?folder=problem_folder fixed the connection issue. Now I’m right back to the original question. Didn’t mean to add to the thread for the connection problem, originally thought it could be related.


(Audrius Butkevicius) #8

This makes no sense, as folders and connections are not related in anyway. When you have issues you usually need to check box sides to understand where the issue is.


(Jnnewton) #9

I’m pretty sure my indexes are have been of whack from a previous upgrade. I don’t know. I found that command via a google search of some sort, tried it on a less important folder and worked my way up. I don’t know why it works or how it affects the data stored by syncthing, I just know that it’s working and I have 2 more folders to do and hopefully everything will carry on without issue. Each time i run it, it wipes out all the “Out of Sync Items” for whatever folder I run it on.


(Jnnewton) #10

Had it all running yesterday, today it’s all back to where I started. 1746 out of sync items across two folders and no failed items. Thinking about setting up a cron job to run that curl command until this gets fixed in the source code.


(Simon) #11

Can you enable the model debug facility (actions->logs) and post the logs here.


(Jnnewton) #12

Maybe this will help. I ran the reset command and it cleaned everything up. Desktop is always connected.

Steps after everything cleaned up on desktop:

  1. Set the model debug facility as requested.
  2. Turned on laptop.
    Result: Server Shows laptop sync at Syncing 95%, 10 items out of sync, no failed items. Folder ID that has out of sync items is fcf5t-uzni9. Both Laptop and Desktop show Up to Date. All machines using identical #include .stglobalignore in .stignore.

Initial Log from server after enabling model debug (ID’s replaced with <LAPTOP_ID> / <DESKTOP_ID>.

2018-07-30 10:28:28 Enabled debug data for "model"
2018-07-30 10:29:28 Established secure connection to <LAPTOP_ID> at     
192.168.2.53:22000-192.168.2.231:56768/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
2018-07-30 10:29:28 Device <LAPTOP_ID> client is "syncthing v0.14.49" named "<LAPTOP_NAME>" at 192.168.2.53:22000-192.168.2.231:56768/tcp-server
2018-07-30 10:29:28 Device <LAPTOP_ID> folder "Documents" (default) is delta index compatible (mlv=2513)
2018-07-30 10:29:28 Device <LAPTOP_ID> folder "Eagle" (fcf5t-uzni9) is delta index compatible (mlv=92839)
2018-07-30 10:29:28 Device <LAPTOP_ID> folder "MPLabX" (grj2s-ohmhx) is delta index compatible, but seems out of sync with reality
2018-07-30 10:29:28 Starting sendIndexes for default to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server (slv=2513)
2018-07-30 10:29:28 Device <LAPTOP_ID> folder "Go" (hkkwp-mck4z) is delta index compatible (mlv=24416)
2018-07-30 10:29:28 Starting sendIndexes for grj2s-ohmhx to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server (slv=0)
2018-07-30 10:29:28 Starting sendIndexes for hkkwp-mck4z to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server (slv=24416)
2018-07-30 10:29:28 Starting sendIndexes for fcf5t-uzni9 to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server (slv=92839)
2018-07-30 10:29:28 sendReceiveFolder/default@0xc4200e9680 pulling (ignoresChanged=false)
2018-07-30 10:29:28 sendReceiveFolder/hkkwp-mck4z@0xc4200e8f00 pulling (ignoresChanged=false)
2018-07-30 10:29:28 sendReceiveFolder/hkkwp-mck4z@0xc4200e8f00 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:28 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:28 sendReceiveFolder/fcf5t-uzni9@0xc4200e9b80 pulling (ignoresChanged=false)
2018-07-30 10:29:28 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:28 sendReceiveFolder/default@0xc4200e9680 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:28 sendReceiveFolder/fcf5t-uzni9@0xc4200e9b80 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:28 sendReceiveFolder/default@0xc4200e9680 changed 0
2018-07-30 10:29:28 progress emitter: bytes completed for default: 0
2018-07-30 10:29:28 model@0xc4200a1200 NeedSize("default"): {0 0 0 0 0 0 []}
2018-07-30 10:29:28 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:28 model@0xc4200a1200 Completion(<LAPTOP_ID>, "default"): 100.000000 (0 / 2056000102 = 0.000000)
2018-07-30 10:29:28 model@0xc4200a1200 Completion(<DESKTOP_ID>, "default"): 100.000000 (0 / 2056000102 = 0.000000)
2018-07-30 10:29:28 Sending indexes for grj2s-ohmhx to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server: 1000 files (<97892 bytes) (initial index)
2018-07-30 10:29:28 sendReceiveFolder/fcf5t-uzni9@0xc4200e9b80 changed 0
2018-07-30 10:29:28 Index (in): <LAPTOP_ID> / "grj2s-ohmhx": 1000 files
2018-07-30 10:29:28 Sending indexes for grj2s-ohmhx to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server: 1000 files (<175363 bytes) (batched update)
2018-07-30 10:29:28 progress emitter: bytes completed for fcf5t-uzni9: 0
2018-07-30 10:29:28 model@0xc4200a1200 NeedSize("fcf5t-uzni9"): {0 0 0 0 0 0 []}
2018-07-30 10:29:28 sendReceiveFolder/hkkwp-mck4z@0xc4200e8f00 changed 0
2018-07-30 10:29:28 Sending indexes for grj2s-ohmhx to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server: 1000 files (<176612 bytes) (batched update)
2018-07-30 10:29:28 model@0xc4200a1200 Completion(<LAPTOP_ID>, "fcf5t-uzni9"): 95.000000 (0 / 233040091 = 0.000000)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "fcf5t-uzni9"): 100.000000 (0 / 233040091 = 0.000000)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:29 Index update (in): <LAPTOP_ID> / "grj2s-ohmhx": 1000 files
2018-07-30 10:29:29 Sending indexes for grj2s-ohmhx to <LAPTOP_ID> at 192.168.2.53:22000-192.168.2.231:56768/tcp-server: 54 files (<9477 bytes) (last batch)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:29 progress emitter: bytes completed for grj2s-ohmhx: 0
2018-07-30 10:29:29 model@0xc4200a1200 NeedSize("grj2s-ohmhx"): {0 0 0 0 0 0 []}
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<LAPTOP_ID>, "grj2s-ohmhx"): 2.982205 (19321575 / 19915496 = 0.970178)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "grj2s-ohmhx"): 100.000000 (0 / 19915256 = 0.000000)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:29 Index update (in): <LAPTOP_ID> / "grj2s-ohmhx": 1000 files
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:29 progress emitter: bytes completed for grj2s-ohmhx: 0
2018-07-30 10:29:29 model@0xc4200a1200 NeedSize("grj2s-ohmhx"): {0 0 0 0 0 0 []}
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<LAPTOP_ID>, "grj2s-ohmhx"): 75.644195 (4850521 / 19915256 = 0.243558)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "grj2s-ohmhx"): 100.000000 (0 / 19915256 = 0.000000)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:29 Index update (in): <LAPTOP_ID> / "grj2s-ohmhx": 79 files
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:29 progress emitter: bytes completed for grj2s-ohmhx: 0
2018-07-30 10:29:29 model@0xc4200a1200 NeedSize("grj2s-ohmhx"): {0 0 0 0 0 0 []}
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<LAPTOP_ID>, "grj2s-ohmhx"): 99.995501 (896 / 19915256 = 0.000045)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "grj2s-ohmhx"): 100.000000 (0 / 19915256 = 0.000000)
2018-07-30 10:29:29 Index update (in): <LAPTOP_ID> / "grj2s-ohmhx": 7 files
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 pulling (ignoresChanged=false)
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 copiers: 2 pullerPendingKiB: 32768
2018-07-30 10:29:29 sendReceiveFolder/grj2s-ohmhx@0xc420e96280 changed 0
2018-07-30 10:29:29 progress emitter: bytes completed for grj2s-ohmhx: 0
2018-07-30 10:29:29 model@0xc4200a1200 NeedSize("grj2s-ohmhx"): {0 0 0 0 0 0 []}
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<LAPTOP_ID>, "grj2s-ohmhx"): 100.000000 (0 / 19915256 = 0.000000)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "grj2s-ohmhx"): 100.000000 (0 / 19915256 = 0.000000)
2018-07-30 10:29:29 progress emitter: bytes completed for hkkwp-mck4z: 0
2018-07-30 10:29:29 model@0xc4200a1200 NeedSize("hkkwp-mck4z"): {0 0 0 0 0 0 []}
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<LAPTOP_ID>, "hkkwp-mck4z"): 100.000000 (0 / 662015189 = 0.000000)
2018-07-30 10:29:29 model@0xc4200a1200 Completion(<DESKTOP_ID>, "hkkwp-mck4z"): 100.000000 (0 / 662015189 = 0.000000)

(Jnnewton) #13

Simon: is the log above what you were requesting?


(Simon) #14

Yes and no: It is the log I was asking for but the important part of your answer was

Until then I interpreted your reports as the actual folders being out of sync, not the remote devices. The remote device out of sync problem is coming up a lot lately and I was unable to pin it down at all. And the logs don’t contain relevant infos for that problem. Sorry I didn’t react earlier.
If you can reproduce it on your setup, you could run Syncthing with model, db and protocol debug facilities enabled on both sides (!) and make those logs available - privately if you are concerned about metadata and I am aware, those logs will be huge, but that’s necessary.


(system) #15

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.