Rapid rescans without making progress

Support
1

I have a folder shared among five devices, of which only three are currently online. All of them keep alternating quickly between “scanning”, “preparing to sync” and “syncing” states for the folder. The only way to stop it is pausing the folder on one device which modified a file.

Interestingly, it is only one single file which changed on device A and is out of sync on B and C. I tried deleting the file on A, which helped. Then copied the same file under a different path and the problem came back. When restarting, everything seems stable after the initial scan, but the rapid cycle starts after a rescan.

Looking at the logs with “scanner” debug facility, I noticed that the index ID for the file keeps climbing rapidly. What exactly should I look for to diagnose this further?

All involved devices on Syncthing v1.7.0. Ubuntu Linux, Synology (package from SynoCommunity, internally auto-updated) and Android.

2

Looks like this could be related to https://github.com/syncthing/syncthing/issues/6827.

Will the fix in v1.7.1 be properly released soon?

3

Not until anyone bothers to try the build to see if it has the desired effect.

1 Like
4

I’ve had this for a different reason in ST 1.5.0 - constantly flickering status . So pls make sure you have no file in place that constantly changes.

5

For v1.7.1, the build artifacts are missing on the GitHub release page. I think those are correct:

6

So far, so good. v1.7.1 linux amd64 seems to run smoothly. No flip flops and no suspicious log entries pointing to a problem here. :slight_smile:

dev A:

image
image982×702 32.8 KB

dev B:

image
image988×554 26.4 KB

7

@Catfriend1 did you have a problem prior to installing 1.7.1?

8

Will try a test build tonight and report back.

9

@calmh Not sure, because I had this flip flopping before we tracked down to another cause. I don’t know if the commit addresses this too.

10

No this is specifically for the “pull …: not found” thing.

11

Not solved with v1.7.1.

During the last test with v1.7.0, I think I saw these failed validating data messages in the model debug log. With v1.7.1 those are not showing up, but still stuck on that one file, alternating status.

Do you have any ideas where this might come from and what debug output might help you @calmh?

12

Could not reproduce the log message with v1.7.0 anymore, but the loop is still there. Partial log below, until I paused the folder to stop it from toggling:

[2V3UU] 2020/07/13 22:31:20.251862 folder.go:169: DEBUG: sendreceive/my-folder@0xc0014a6380 Running something due to request
[2V3UU] 2020/07/13 22:31:20.440050 model.go:892: DEBUG: Index update (in): ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:20.456932 model.go:892: DEBUG: Index update (in): rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:20.459845 folder_sendrecv.go:163: DEBUG: sendreceive/my-folder@0xc0014a6380 pulling
[2V3UU] 2020/07/13 22:31:20.459895 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:20.460115 folder_sendrecv.go:1145: DEBUG: sendreceive/my-folder@0xc0014a6380 taking shortcut on path/to/problematic/file.mp3
[2V3UU] 2020/07/13 22:31:20.465475 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 1 on try 1
[2V3UU] 2020/07/13 22:31:20.465529 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:20.465802 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 0 on try 2
[2V3UU] 2020/07/13 22:31:20.465865 model.go:1926: DEBUG: indexSender@0xc00443bce0 for my-folder to  at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:20.465965 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:20.466078 model.go:1926: DEBUG: indexSender@0xc00350c000 for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:20.466138 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:20.466216 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:21.067240 folder.go:177: DEBUG: sendreceive/my-folder@0xc0014a6380 Scan due to watcher
[2V3UU] 2020/07/13 22:31:21.518404 model.go:892: DEBUG: Index update (in): ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:21.519502 folder_sendrecv.go:163: DEBUG: sendreceive/my-folder@0xc0014a6380 pulling
[2V3UU] 2020/07/13 22:31:21.519576 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:21.519918 folder_sendrecv.go:1145: DEBUG: sendreceive/my-folder@0xc0014a6380 taking shortcut on path/to/problematic/file.mp3
[2V3UU] 2020/07/13 22:31:21.524842 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 1 on try 1
[2V3UU] 2020/07/13 22:31:21.524906 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:21.525083 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 0 on try 2
[2V3UU] 2020/07/13 22:31:21.525135 model.go:1926: DEBUG: indexSender@0xc00443bce0 for my-folder to  at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:21.525160 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:21.525329 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:21.525503 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:21.526803 model.go:1926: DEBUG: indexSender@0xc00350c000 for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:21.539242 model.go:892: DEBUG: Index update (in): rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:22.581324 model.go:892: DEBUG: Index update (in): ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:22.582111 folder_sendrecv.go:163: DEBUG: sendreceive/my-folder@0xc0014a6380 pulling
[2V3UU] 2020/07/13 22:31:22.582179 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:22.582433 folder_sendrecv.go:1145: DEBUG: sendreceive/my-folder@0xc0014a6380 taking shortcut on path/to/problematic/file.mp3
[2V3UU] 2020/07/13 22:31:22.587254 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 1 on try 1
[2V3UU] 2020/07/13 22:31:22.587321 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:22.587572 model.go:1926: DEBUG: indexSender@0xc00350c000 for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:22.587691 model.go:1926: DEBUG: indexSender@0xc00443bce0 for my-folder to  at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:22.587772 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 0 on try 2
[2V3UU] 2020/07/13 22:31:22.587885 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:22.588123 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:22.588221 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:22.610455 model.go:892: DEBUG: Index update (in): rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:22.763674 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:22.764207 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:22.764472 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:23.630565 model.go:892: DEBUG: Index update (in): ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:23.631694 folder_sendrecv.go:163: DEBUG: sendreceive/my-folder@0xc0014a6380 pulling
[2V3UU] 2020/07/13 22:31:23.631777 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:23.632128 folder_sendrecv.go:1145: DEBUG: sendreceive/my-folder@0xc0014a6380 taking shortcut on path/to/problematic/file.mp3
[2V3UU] 2020/07/13 22:31:23.637041 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 1 on try 1
[2V3UU] 2020/07/13 22:31:23.637151 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:23.637499 model.go:1926: DEBUG: indexSender@0xc00350c000 for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:23.637645 model.go:1926: DEBUG: indexSender@0xc00443bce0 for my-folder to  at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:23.637959 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 0 on try 2
[2V3UU] 2020/07/13 22:31:23.638161 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:23.638486 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:23.638633 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:23.650275 model.go:892: DEBUG: Index update (in): rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:24.698038 model.go:892: DEBUG: Index update (in): ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:24.699187 folder_sendrecv.go:163: DEBUG: sendreceive/my-folder@0xc0014a6380 pulling
[2V3UU] 2020/07/13 22:31:24.699322 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:24.699589 folder_sendrecv.go:1145: DEBUG: sendreceive/my-folder@0xc0014a6380 taking shortcut on path/to/problematic/file.mp3
[2V3UU] 2020/07/13 22:31:24.704409 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 1 on try 1
[2V3UU] 2020/07/13 22:31:24.704468 folder_sendrecv.go:235: DEBUG: sendreceive/my-folder@0xc0014a6380 copiers: 2 pullerPendingKiB: 32768
[2V3UU] 2020/07/13 22:31:24.704831 folder_sendrecv.go:188: DEBUG: sendreceive/my-folder@0xc0014a6380 changed 0 on try 2
[2V3UU] 2020/07/13 22:31:24.704894 model.go:1926: DEBUG: indexSender@0xc00443bce0 for my-folder to  at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:24.704920 model.go:1926: DEBUG: indexSender@0xc00350c000 for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<1457 bytes)
[2V3UU] 2020/07/13 22:31:24.705076 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:24.705289 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:24.705369 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:24.715199 model.go:892: DEBUG: Index update (in): rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr / "my-folder": 1 files
[2V3UU] 2020/07/13 22:31:24.766727 progressemitter.go:296: DEBUG: progress emitter: bytes completed for my-folder: 0
[2V3UU] 2020/07/13 22:31:24.766958 model.go:777: DEBUG: model@0xc001582780 Completion(ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd, "my-folder"): 95.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:24.767060 model.go:777: DEBUG: model@0xc001582780 Completion(rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr, "my-folder"): 100.000000 (0 / 5380937346 = 0.000000)
[2V3UU] 2020/07/13 22:31:24.991989 folder.go:145: DEBUG: sendreceive/my-folder@0xc0014a6380 exiting
[2V3UU] 2020/07/13 22:31:24.992217 model.go:1347: INFO: Connection to ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd-ddddddd at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: pausing folder "yikes" (my-folder)
[2V3UU] 2020/07/13 22:31:24.992288 model.go:1347: INFO: Connection to rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr-rrrrrrr at 192.168.0.108:56146-192.168.0.20:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: pausing folder "yikes" (my-folder)
[2V3UU] 2020/07/13 22:31:24.992323 model.go:1896: DEBUG: Exiting indexSender for my-folder to  at 192.168.0.108:53328-37.187.107.191:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256: <nil>
[2V3UU] 2020/07/13 22:31:24.992355 model.go:504: INFO: Paused folder "yikes" (my-folder) (sendreceive)
13

I’d like to try the 1.7.1 patch since I am also getting rapid rescans. I’m currently installing form the official stable Debian/Ubuntu PPA. How do I install the patch without messing up future version updates from the PPA? Thanks!

14

1.7.1 is available in apt now.

@acolomb that looks like https://github.com/syncthing/syncthing/pull/6799 or https://github.com/syncthing/syncthing/pull/6797 which is 1.8.0 material (RC coming today this week).

1 Like
15

I pulled the update last night and un-paused the folder I was having issues with. This morning every has finished syncing and all is happy once again. Thanks for the patch!

1 Like
16

Sorry I cannot reproduce this issue anymore. Forgot to take a DB backup before trying with v1.7.1, after which the problem exhibited different log messages. I also tried the main branch at that point and the toggling stopped for good. Even after going back to v1.7.0.

Now I am on v1.7.1 from the APT repo and everything seems stable. So whatever the upgrade did to the DB, any problematic entries seem to be fixed afterwards. Sorry I can’t help to further diagnose the condition.

17

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