Isn't making progress, Pausing puller

My two sites were almost completely sync’d. There were some things stuck so I gave attention to the items in the top of the out of sync list that I thought were the issues. One site had a Failed item because a folder wasn’t empty. The only thing in it was a .DS_Store file which is ignored so I don’t know why it couldn’t be forced removed. I deleted it and failed item went away. Next I had some files that had / in the file name. I assumed these were problems and I started to rename them to get rid of the /. Both sites ended up with duplicate files that had one version with and one version without the /. Perhaps I don’t understand staggered file versioning but I thought maybe changing one side would change the other. I paused both sides and deleted all the files with the / in the names the resumed both sides. Now I have stuck things at each site but the list of files is different on each site and both sites logs just continue with the Pausing Puller for 1m0s message. I need help determining what is really the cause of the freeze.

Is it safe to assume that the first item in the list of out of sync items is causing a problem? Is there a way to get more info in the log generated to see what the hang up is? I can’t really determine from my log entries what is going on very well.

Please read the docs on ignores regarding the .DS_Store.

The rest of your problems I can’t explain as you haven’t provided any logs or anything indicating what the actual error is.

One out of sync item is not going to block the rest usually, unless it’s actually in the way of the others. So for example if we can’t create folder X because of permissions, obviously all files within that folder will be stuck too.

I’ve read the docs. It says the folder should have been deleted but it wasn’t I had to do it manually. -just reread and see the ?d prefix.

The actual error is that the files I renamed are still listed as out of sync and the log is just filling up with ‘isn’t making progress’ Is this not an error? I don’t want to see my log filled with this when I have to use a lot of interpretation to understand what is happening with syncthing.

Also, why isn’t there a date stamp along with time stamp in the log file? logs.zip (49.8 KB)

You should double check that the folder ID is the same, and it’s unpaused on both sides, and that it’s shared with each other on both sides, as there is a ton of errors about unshared folders, devices being paused etc, also make sure both sides are sharing the right folders with the right devices.

Worst case, shut both sides down, run syncthing -reset-database on both sides and start them up, but that’s only needed if you did something really ugly like go syncthing to advertise a file, then later ignored it so it’s no longer available anywhere tec.

I’m certain the folder ID’s are fine. They have already sync’d 2TB of data. The other paused folders are fine. They are paused while I get this large share working properly. I don’t really want to get to a worst case and reset the database. This is a production system that I need to administer and I want to be able to look at the status and know there aren’t any problems. Right now there are problems and I need to understand what they are. Will using STTRACE offer me any help in figuring this out? And please can you answer why the logs don’t show dates and only times?

Thanks.

The logs don’t show dates and only times because we only care about time. You can try setting STTRACE=model which will make it verbose and might explain the errors a bit better.

Also, -logflags

1 Like

Using ‘model’ I’m seeing this on repeat, is it normal?

[AIOGO] 2017/09/22 10:38:50.882213 model.go:126: DEBUG: Entering the backoff state. [AIOGO] 2017/09/22 10:38:50.882259 model.go:126: DEBUG: model: Failed service ‘&versioner.Staggered{cleanInterval:3600, folderFs:(*fs.walkFilesystem)(0xc4201818f0), versionsFs:(*fs.walkFilesystem)(0xc42003f6f0), interval:[4]versioner.Interval{versioner.Interval{step:30, end:3600}, versioner.Interval{step:3600, end:86400}, versioner.Interval{step:86400, end:592000}, versioner.Interval{step:604800, end:31536000}}, mutex:(*sync.Mutex)(0xc422e96a50), stop:(chan struct {})(0xc42322bc20), testCleanDone:(chan struct {})(nil)}’ (7.999477 failures of 5.000000), restarting: false, error: runtime error: slice bounds out of range, stacktrace: goroutine 2865 [running]: github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1.1(0xc4201e81c0, 0x0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:448 +0xbc panic(0x1698c20, 0x1cde820) /usr/local/Cellar/go/1.9/libexec/src/runtime/panic.go:491 +0x283 github.com/syncthing/syncthing/lib/versioner.(*Staggered).clean.func1(0xc4213c25e0, 0x9, 0x1c91780, 0xc4209bc930, 0x0, 0x0, 0x170d320, 0xc4209bc930) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/versioner/staggered.go:132 +0x4f0 github.com/syncthing/syncthing/lib/fs.(*walkFilesystem).walk(0xc42003f6f0, 0xc4213c25e0, 0x9, 0x1c91780, 0xc4209bc930, 0xc420840060, 0x0, 0x0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/fs/walkfs.go:41 +0x81 github.com/syncthing/syncthing/lib/fs.(*walkFilesystem).walk(0xc42003f6f0, 0x175eb55, 0x1, 0x1c91780, 0xc4202560a0, 0xc420840060, 0x0, 0xc420840060) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/fs/walkfs.go:66 +0x3ef github.com/syncthing/syncthing/lib/fs.(*walkFilesystem).Walk(0xc42003f6f0, 0x175eb55, 0x1, 0xc420840060, 0xc421e14060, 0x0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/fs/walkfs.go:88 +0xdd github.com/syncthing/syncthing/lib/versioner.(*Staggered).clean(0xc4201e62d0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/versioner/staggered.go:116 +0x354 github.com/syncthing/syncthing/lib/versioner.(*Staggered).Serve(0xc4201e62d0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/lib/versioner/staggered.go:81 +0x40 github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1(0xc4201e81c0, 0x0, 0x2f1cc80, 0xc4201e62d0) /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:454 +0x63 created by github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService /private/tmp/syncthing-20170920-76544-1e6ib7u/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:444 +0x5b

[AIOGO] 2017/09/22 10:38:52.605108 rwfolder.go:196: DEBUG: sendReceiveFolder/default@0xc4201a66c0 skip (curSeq == prevSeq) 0 true [AIOGO] 2017/09/22 10:38:52.605181 rwfolder.go:196: DEBUG: sendReceiveFolder/Sync@0xc4201a6240 skip (curSeq == prevSeq) 11830 true [AIOGO] 2017/09/22 10:38:53.055184 rwfolder.go:196: DEBUG: sendReceiveFolder/S94@0xc4201a6d80 skip (curSeq == prevSeq) 0 true [AIOGO] 2017/09/22 10:38:57.005166 rwfolder.go:196: DEBUG: sendReceiveFolder/ArtBase@0xc4201a6b40 skip (curSeq == prevSeq) 14627 true [AIOGO] 2017/09/22 10:39:02.705499 rwfolder.go:196: DEBUG: sendReceiveFolder/Sync@0xc4201a6240 skip (curSeq == prevSeq) 11830 true [AIOGO] 2017/09/22 10:39:02.705579 rwfolder.go:196: DEBUG: sendReceiveFolder/default@0xc4201a66c0 skip (curSeq == prevSeq) 0 true [AIOGO] 2017/09/22 10:39:03.155526 rwfolder.go:196: DEBUG: sendReceiveFolder/S94@0xc4201a6d80 skip (curSeq == prevSeq) 0 true

and also a lot of

[AIOGO] 2017/09/22 10:38:36.179177 rwfolder.go:1367: DEBUG: file modified but not rescanned; not finishing: [AIOGO] 2017/09/22 10:38:36.179222 progressemitter.go:225: DEBUG: progress emitter: deregistering Shared ART ADVISORY/INVENTORY/Brown, Glenn/GB_3/IMG_2015.JPG [AIOGO] 2017/09/22 10:38:36.179549 rwfolder.go:1070: DEBUG: sendReceiveFolder/Shared@0xc4201a6480 need file ART ADVISORY/INVENTORY/Brown, Glenn/GB_3/IMG_2014.JPG; copy 0, reused 1

on some files

Are you using inotify or something like that? Pressing the rescan button should be sufficient.

No, not installed. Scanning is happening 240 second intervals.

I’ve use the REST API to investigate a little. Here is the db/file info on one of the files that is stuck

{
"availability": null,
"global": {
"deleted": false,
"invalid": false,
"modified": "2013-10-15T14:09:24-04:00",
"name": "Images/TWO BOYS, 2013/Laurie Simmons Two Boys Inventory Info.pdf",
"noPermissions": true,
"numBlocks": 6,
"permissions": "0660",
"sequence": 95691,
"size": 662818,
"type": 0,
"version": [
  "AIOGOTD:1"
],
},
"local": {
"deleted": false,
"invalid": false,
"modified": "2013-10-15T14:09:24-04:00",
"name": " Images/TWO BOYS, 2013/Laurie Simmons Two Boys Inventory Info.pdf",
"noPermissions": true,
"numBlocks": 6,
"permissions": "0660",
"sequence": 95691,
"size": 662818,
"type": 0,
"version": [
  "AIOGOTD:1"
],
}
}

Why is availability showing as null? …or rather, what would it take to override that null with an id? Can I manually generate an ID or something?

No, it means device with ID starting AIOGOTD advertised this file, but we are not connected to it, or it’s no longer available.

But the file actually is there and available. Does this mean the scanner cannot find it or does it mean that its not going to try to find it?

I think you are on the wrong side, as in, on the side that has the file, it’s on disk, at version 1, and it’s not trying to download it.

Both sides have the file. I’ll check the same file info on the other side to see what the API says…

This is from the other side…

{
"availability": null,
"global": {
"deleted": false,
"invalid": false,
"modified": "2013-10-15T14:09:24-04:00",
"name": " Images/Two Boys, 2013/Laurie Simmons Two Boys Inventory Info.pdf",
"noPermissions": true,
"numBlocks": 6,
"permissions": "0600",
"sequence": 69345,
"size": 662818,
"type": 0,
"version": [
  "2JOAHQM:1"
],
},
"local": {
"deleted": false,
"invalid": false,
"modified": "2013-10-15T14:09:24-04:00",
"name": " Images/Two Boys, 2013/Laurie Simmons Two Boys Inventory Info.pdf",
"noPermissions": true,
"numBlocks": 6,
"permissions": "0600",
"sequence": 69345,
"size": 662818,
"type": 0,
"version": [
  "2JOAHQM:1"
],
}
}

They are simply not sharing the folder that contains this file mutually, as each of them claims that they are the only device that has seen the file.

Okay, so we can determine then that this is what Synchthing thinks to be true, but it is not true, so how did this happen and how can I correct it? Can I just shut it down on both sides and move the file out of the directories? Start back up, let it scan, then put it back?

Sorry, now I see it:

" Images/TWO BOYS, 2013/Laurie Simmons Two Boys Inventory Info.pdf"

versus

" Images/Two Boys, 2013/Laurie Simmons Two Boys Inventory Info.pdf",

You are hitting https://github.com/syncthing/syncthing/issues/1787 The only way to fix this is to normalize the cases, and reset the database on both sides.

Oh I see what’s going on, someone on one side decided to rename the folder in CAPS. users are doing clean up, etc…