Oneother item stuck in ‘Out of Sync Items’

cosas · August 7, 2018, 11:43am

Same issue with 5 files spread in 2 folders.

All devices are/were 0.14.49 stable All 5 files are shown stuck pushing in deviceA to deviceB, only one showing this state for folderA, the 4 others for folderB. GET /rest/db/file below for the first one, so 4 instances of the file. sameness tested OK with shasum256 in the 4 places (2 in deviceA/foldersA+B,2 in deviceB/foldersA+B).

Topology of folderA: triangular rw & no ignores devicesABC (friend’s deviceC is offline since I met the issue). Usually, devicesA & B are in my LAN and deviceC is remote. At the time the file was first dropped with many others in deviceA-folderA and synch started to deviceC, these 2 laptops were in another holidays LAN with my cellular phone as the edge gateway mobile AP (with a single client: a ddwrt router as client doing virtualAP(not WAP, i.e. different LAN segment from mobile AP) for the laptops, so I’m 100% sure they were in the same LAN), and when I realized/remembered my deviceB was involved & online, I first paused deviceB in deviceC, then a bit later I also thought and paused deviceB in deviceA so I didn’t eat all my mobile data plan. When I went back home, I resumed devB in devA, then I saw the issue when sync was all done, but I’m not sure my friend resumed devB in his devC (whatever, devC is offline since, I’m sure of this because my deviceA shows it so since 4 days). That’s all folks for circumstancies/environment, and sorry if this not useful.

Topology of folderB: multi symetrical link to several friends devices with deviceB and deviceC, and deviceA only shares with deviceB (not directly with deviceC and others).

DeviceA failing to push this file to DeviceB in folderA:

{
  "availability": null,
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 787,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 787,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  }
}

DeviceA succeded to push this file to DeviceB in folderB:

{
  "availability": [
    {
      "id": "LF5AG4N-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 828,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 845,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  }
}

DeviceB not asking anything from folderA (GET /rest/db/samefile):

{
  "availability": [
    {
      "id": "772V4XB-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 345,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 345,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  }
}

DeviceB not asking anything from folderB (GET /rest/db/samefile):

{
  "availability": [
    {
      "id": "YHJRSXZ-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    },
    {
      "id": "XXH25YP-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    },
    {
      "id": "772V4XB-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 5895,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-08-01T16:03:30+02:00",
    "modifiedBy": "772V4XB",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180801_160331-GP-dsc03033.jpg",
    "noPermissions": false,
    "numBlocks": 69,
    "permissions": "0664",
    "sequence": 828,
    "size": 8934832,
    "type": 0,
    "version": [
      "772V4XB:1"
    ]
  }
}

AudriusButkevicius · August 7, 2018, 12:13pm

Summon @calmh and @imsodin

imsodin · August 7, 2018, 12:32pm

Thanks for providing this info!

The rest calls are all from the same file, but you are saying it’s two folders. Do you have identical directories or is it the same directory with two folders on them? If you could add the rest query above the output that would help.

Device A shows device B as out of sync, all devices show their local folders as up-to-date and in reality are up-to-date, correct?

cosas · August 7, 2018, 12:34pm

Yes correct. But maybe something will change when deviceC will come back online… let’s wait some days and see…

imsodin · August 7, 2018, 12:38pm

I posted the reply before too early. Can you please answer this part too - thanks.

cosas · August 7, 2018, 12:55pm

The paths to directories for the 2 shared folders are really different, not nested nor same path for the two shares in no device:

/home/me/Sync/folderA/…file

/home/me/Sync/folderB/…file

The GET rest/db/file posted above are from 1rst to 4th:

devAfoldAfile (issue devA wants to push but can’t)

devAfoldBfile (just in case this may add some useful info - no issue here)

devBfoldAfile (~issue~ here is devB has the file, so doesn’t asks it, what is intented - read it’s intented it doesn’t pull)

devBfoldBfile (just in case this may add some useful info - no issue here)

as posted above each GET

cosas · August 12, 2018, 12:59pm

Friend’s deviceC went online, synced missing files everywhere needed, but the issue remained for the file above in folderA and the 4 other files in folderB.

Now I deleted the subdir in folderA from devA, the subdir/file above isn’t shown anymore in devA’s GUI, although I can still query it OK in devA’s folderA (and folderA is UpToDate everywhere and the file now only exists in folderB).

Now I can’t see the issue for the file above, let’s have a look to the case of one from 4 stuck files for a total size of 4,87MB (among ~700 files without issue) in folderB:

I can’t see something wrong in REST queries, but maybe “sequence” is wrong somewhere (I don’t know how to understand this data)

deviceA:

curl -k -X GET -H "X-API-Key: devA-APIkey" 'https://localhost:8384/rest/db/file?folder=folderB-id&file=201807%2028%20Ibarra/20180714_152505-FV-20180714_152505.jpg'
{
  "availability": null,
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-07-14T15:25:04+02:00",
    "modifiedBy": "DEVICEA",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180714_152505-FV-20180714_152505.jpg",
    "noPermissions": false,
    "numBlocks": 9,
    "permissions": "0664",
    "sequence": 924,
    "size": 1078062,
    "type": 0,
    "version": [
      "DEVICEA:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-07-14T15:25:04+02:00",
    "modifiedBy": "DEVICEA",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180714_152505-FV-20180714_152505.jpg",
    "noPermissions": false,
    "numBlocks": 9,
    "permissions": "0664",
    "sequence": 924,
    "size": 1078062,
    "type": 0,
    "version": [
      "DEVICEA:1"
    ]
  }
}

DeviceB:

curl -k -X GET -H "X-API-Key: devB-APIkey" 'https://localhost:8384/rest/db/file?folder=folderB-id&file=201807%2028%20Ibarra/20180714_152505-FV-20180714_152505.jpg'
{
  "availability": [
    {
      "id": "DEVICEA-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX-XXXXXXX",
      "fromTemporary": false
    }
  ],
  "global": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-07-14T15:25:04+02:00",
    "modifiedBy": "DEVICEA",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180714_152505-FV-20180714_152505.jpg",
    "noPermissions": false,
    "numBlocks": 9,
    "permissions": "0664",
    "sequence": 3244,
    "size": 1078062,
    "type": 0,
    "version": [
      "DEVICEA:1"
    ]
  },
  "local": {
    "deleted": false,
    "ignored": false,
    "invalid": false,
    "localFlags": 0,
    "modified": "2018-07-14T15:25:04+02:00",
    "modifiedBy": "DEVICEA",
    "mustRescan": false,
    "name": "201807 28 Ibarra/20180714_152505-FV-20180714_152505.jpg",
    "noPermissions": false,
    "numBlocks": 9,
    "permissions": "0664",
    "sequence": 937,
    "size": 1078062,
    "type": 0,
    "version": [
      "DEVICEA:1"
    ]
  }
}

EDIT: the ignores reported in the screenshot are only cosmetic:

(?d)(?i)*.ini
(?d)(?i)*.lnk
(?d)(?i)*Thumb*.db

imsodin · August 12, 2018, 1:45pm

Thanks again for the information.

It shows the same thing as previous reports: Both devices are up to date, but device A hasn’t registered, that device B has the up-to-date version of that file. This means either device B never sent that file info, or device A somehow didn’t register it in the db. I can’t see how the latter should happen, the former could be due to a wrong Sequence, but again I have no idea how that would happen.

Right now the only thing that I would expect to potentially help me (!) understand the cause of this issue, is if you could record logs with db and model (and maybe for good measure protocol) debug facilities enabled, while the index data is exchanged. Meaning you’d have to run Syncthing with -reset-deltas and the mentioned debug facilities and then get it into this state (one side showing the remote as out of sync) again while recording those logs. I know that’s quite a handful, as it’s unclear how to reproduce it exactly.

AudriusButkevicius · August 12, 2018, 2:31pm

I suspect if you reset the state you won’t see the problem.

One thing that catches my eye is that filenames are very long. I wonder if this is some sort of stuff being dropped in the protocol package due to names or lengths which then leads to this.

Also, getting a copy of both of the devices databases might help too.

cosas · August 13, 2018, 2:01pm

I will reword to make sure I understand well, so please correct me if I’m wrong:

ATM there is no way to diagnose this occurrence of this issue. For hypothetical future occurrence(s), help may be provided by setting ST to run on both side with db, model and protocol logging debug facilities, after I reset ST to a normal display/behaviour regarding the current occurrence (reset-deltas or fake-edit the 4 files)… and wait/hope the problem arise again one day.

@Audrius, as many files here have even longer names I just can’t believe this…

You would like the whole DB. I guess DB before issue arises, and even after isn’t it? How can I catch the DB in the state it was before the issue happens ?

Yesterday night I noticed something maybe interesting just after I saved an editing job on an already-synced-OK-not-showing-this-issue file in folderB/deviceA: as I said in OP, devA shares folderB only with devB, then devB shares folderB with some other devices, multisymetrical. I’m on holidays with a poor Internet speed so although the file is little I had time enough to observe the following on devB (regards to remote desktop). As soon as I saved on devA and ST saw the change, it started syncing. On devB (fully UtD with devA and all others online just before), then even the file download wasn’t yet fully done, I could see ST beginning to push the file to the others. I don’t know if this behaviour is intended and/or can generate weird sequences.

I also repeat for memory that all files were initially dropped in devA/foldA and later copied to devA/foldB.

Thank you boyz again and again for your job on ST.

imsodin · August 13, 2018, 2:07pm

DB right now, as the problem is present, is what we are after. So you could stop Syncthing on device A, tar/zip up the db folder and make it available. Whether or not we still need logs after that remains to be seen.

And yes, you understand correctly. The problem is, I need logs before/at the time the problem starts existing. After that, the logs only show the problem is there, but not how it happened.

As to your observation: There is the functionality to share from partially synced files, but I have never worked with that code, so I don’t know how that actually works and whether it really is the reason for your observation.

cosas · August 13, 2018, 2:55pm

Damn’d, I thought too soon I understood OK : I fake edit the 4 files and the issue disappeared. Whatever, I set right now the logging settings for the next time. Sorry Simon

Damn’d again : login facilities won’t survive a restart

I read man and doc on howto/example syntax for my startup applications (ubuntu) to enable STTRACE…

imsodin · August 13, 2018, 3:13pm

You probably shouldn’t run it as usual on ubuntu with all those debug options enabled, as it is probably started as a systemd unit, meaning your system log would be flooded. You can either run it manually and capture the logs in a file or adjust the systemd unit to redirect stdout to a file instead of the system log. If you need assistance with that, just ask.

cosas · August 13, 2018, 3:50pm

Simon, I start ST with per user app startup. I think I found because running the same command line from terminal starts ST with facilities enabled… Although µs time stamps won’t show in GUI log, they are in terminal… but custom log file stops filling when I exit the terminal, even ST is still running and logging in the GUI (I added a “&” at the end of my one-liner in terminal so that I can exit and let ST running: STTRACE=model,protocol,db,scanner syncthing -logfile=$HOME/.config/syncthing/custom_debug.log &

cosas · August 13, 2018, 4:07pm

hmmm, I can’t let this to run 24/24 until issue comes back : already 15MB in some minutes

imsodin · August 13, 2018, 4:18pm

I can see the problem You don’t happen to have a big storage disk that you can point this to? Once the problem comes up, I can ask you to run some grep queries over it to locate the interesting period and extract that. Also you can periodically ditch it if the problem hasn’t come up.

cosas · August 13, 2018, 6:49pm

OK, I’ll do the job by hand just before I drop a new big bunch in ST. Bye Simon.

BTW, now I know how to get these traces, would you be interested by an extract about another post related to !ignores where deviceA constantly fills the log every one minute when no changes at all happened?

imsodin · August 13, 2018, 6:55pm

Thanks!

I honestly can’t remember what that was about, but sure, bug reports with good logs are always welcome

system · September 12, 2018, 7:04pm

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