What makes Syncthing decide when to send data or not

I am 110% certain that message means there are errors.

1 Like

But not in this case. The folder that the error -isn’t making sync progress - retrying in 12h20m35.4700432s relates to the one that syncs when it is the only one that isn’t paused then, when all the other jobs are unpaused and scan / sync will then stops syncing. It’s not out of sync, it’s just stops syncing and the retrying in x

So having ran 1.3.4 as a baseline, I can confirm I don’t have the issue…

image

image

This is the folder that’s having issues

on 1.5.0 the one highlighted would now be stalled and downloading nothing, but it’s happily downloading at 17.5.

For this reason I think 110% that it’s a coding issue.

It should print messages before the “not making progress” explaining why its not making progress.

1 Like

So although it’s not the same 12hr retry, it’s close enough…

[RTF25] 07:04:04 INFO: Connected to already connected device OJHKKMP (existing: 192.168.16.123:22000-/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256 new: 192.168.16.123:22000-8/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256)

[RTF25] 07:04:08 INFO: Connection to OJHKKMP- at 192.168.16.123:22000-/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: reading message: read tcp 192.168.16.123:22000->: wsarecv: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-501f00000000.vhdx”): pull: connection closed

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): pull: connection closed

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Logs\Backup_Error-25-01-2020_20-00-08.log”): pull: peers who had this file went away, or the file has changed while syncing. will retry later

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-501f00000000.vhdx”): no connected device has the required version of this file

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Logs\Backup_Error-25-01-2020_20-00-08.log”): no connected device has the required version of this file

[RTF25] 07:04:08 INFO: Puller (folder " " ( ), item “WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): no connected device has the required version of this file

[RTF25] 07:04:08 INFO: " " ( ): Failed to sync 6 items

[RTF25] 07:04:08 INFO: Folder " " ( ) isn’t making sync progress - retrying in 6h32m4.3702756s.

But neither the file nor remote devices have gone away. The earlier screen shots show that there was connectivity, St simply decides that it’s no longer going to sync. Could the deadlock bug cause such an error to occur?

1.3.4 has been running for 23 hours now and no issues…

folder with issue is indicated with a yellow box. Nothing has changed other than going back to 1.3.4 and changing the db in the config back to 29. Files were not touched, I have not remoted into the remote devices and made any changes to ‘force’ this to work’.

The device has gone away, as indicated in the logs showing the connection getting closed.

Why it has gone away it’s not clear, you could check the logs on the other side.

Perhaps it was a brief disconnect, but again, it’s not really clear with the logs available.

I suggest you capture logs for a longer period of time of nothing happening and then upload them somewhere.

Out of interest, what determines the ‘retrying in’ hr’s length of time? I restarted the remote device and will take mine back to 1.5.0 rc-2 and noticed in my log the retry time remains high…

[RTF25] 12:24:25 INFO: " " ( ): Failed to sync 1 items

[RTF25] 12:24:25 INFO: Folder “” ( ) isn’t making sync progress - retrying in 21h14m5.9673995s.

This error is legitimate since the remote device is restarting, but the 21hrs 14 minutes seems a ridiculously long time to recheck.

Just to reiterate in case it got overlooked: That retry time only applies if nothing else changes: If a device connects, indexes are received from a remote or changes scanned, a pull is retried immediately regardless of that time.

The default pause is 1 minute, which gets increased to 60*1min=1h. It is configurable through the folder config item PullerPauseS. Given the huge times in your logs, that must be changed on your device.

Otherwise what Audrius said: More logs results in more relevant help.

PullerPauseS are all at 0. Unlimited? I will reset them all to 1

0 should mean default, i.e. capped at 1h. Apparently it isn’t capped, so there’s a bug. However as explained shouldn’t be related to the problems you describe and also wasn’t touched as far as I remember since 1.3.4. I’ll look into it.

2 Likes

Thanks Simon.

I’m going to now leave St alone for a few days. Concurrency is at 0 so there is enough folders running that it can make good headway.

So left it for a few days, syncing the big files mainly, all was going fine, I was unpausing other folders, that was fine, trying to avoid any excessive scanning, but then tonight it fell over but with an error I had not seen before… local error: tls: bad record MAC

[RTF25] 20:21:26 INFO: Connection to OJHKKMP at 192.168.16.123:22000-:64513/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: reading message: local error: tls: bad record MAC

[RTF25] 20:21:26 INFO: Puller (folder “” (), item “\WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): pull: connection closed

[RTF25] 20:21:26 INFO: Puller (folder “” (), item “\WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): no connected device has the required version of this file

[RTF25] 20:21:26 INFO: “” (): Failed to sync 1 items

None of the other folders within the same remove device has failed only the one job although to be fair they have been up to date for most of the day…

image

Thought I would mention it as there’s few threads on the matter when I searched the forum. I suspect it’s safe to ignore.

This is getting frustrating. This job plods along and then for no reason decides to stop

image

[RTF25] 13:37:47 INFO: Puller (folder “z-Irvine-hyperv” (irvine-hyperv), item “backup_to_usb\WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): pull: connection closed

[RTF25] 13:37:47 INFO: Puller (folder “z-Irvine-hyperv” (irvine-hyperv), item “backup_to_usb\WindowsImageBackup\HostSvr\Backup 2020-04-26 190018\00b7974a-0000-0000-0000-00093d000000.vhdx”): no connected device has the required version of this file [RTF25] 13:37:47 INFO: “z-Irvine-hyperv” (irvine-hyperv): Failed to sync 1 items

[RTF25] 13:37:47 INFO: Folder “z-Irvine-hyperv” (irvine-hyperv) isn’t making sync progress - retrying in 18h33m4.564621s.

[RTF25] 13:37:48 INFO: “z-Irvine-hyperv” (irvine-hyperv): Failed to sync 1 items

[RTF25] 13:37:48 INFO: Folder “z-Irvine-hyperv” (irvine-hyperv) isn’t making sync progress - retrying in 2m0.069s.

But there’s been no loss of connection, all the other jobs are fine, including folders related to the same remote device. Then it will spend 3 hours rescanning the file - even on a SATA drive because it’s nearly a Tb

Sounds very much like file was changed on the source either while it was initially scanned or while it was transferring now.

(The “connection closed” and “bad MAC” are something else.)

The remote end is

so the last scan was yesterday, probably due to the upgrade. I have the rescan disabled and only the watcher enabled. This is a drive just for my use only, no staff use it, it’s not shared. I only usually update the external backup file once a month and I only pull a new one if I have a previous version already here. I can guarantee that the files are not touched in any way at either end. So far as I know their broadband has been connected all the time, no disconnects.

But, as I have mentioned before, under 1.3.4 I don’t have this issues. In my mind something is tripping over the folder to think that a rescan is needed. I get a lot of “no connected device has the required version of this file”, which for the most part are correct as I have some folders on pause. But it regularly appears on folders that are running.

Is there anything I can do to set extra logging to see why it stops?

In the cases you’ve showed the reason it stops is because the file either changes, or the device that has the file disconnects (as confirmed by the connection closed message).

You should check the logs on the other side why it decides to disconnect.

this is all that’s on the remote end around the time it disconnected

[OJHKK] 13:36:15 INFO: Connection to RTF2535- at 192.168.0.210:62082-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: writing message: write tcp 192.168.0.210:62082->:22000: wsasend: An existing connection was forcibly closed by the remote host.

[OJHKK] 13:36:44 INFO: Established secure connection to RTF2535 at 192.168.0.210:50605-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

[OJHKK] 13:36:44 INFO: Device RTF2535- client is “syncthing v1.5.0” named “Backup Server” at 192.168.0.210:50605-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

[OJHKK] 13:36:44 INFO: Connection to RTF2535- at 192.168.0.210:50605-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: reading length: EOF

[OJHKK] 13:37:44 INFO: Established secure connection to RTF2535- at 192.168.0.210:50611-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

[OJHKK] 13:37:44 INFO: Device RTF2535- client is “syncthing v1.5.0” named “Backup Server” at 192.168.0.210:50611-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

[OJHKK] 13:37:44 INFO: Connection to at 192.168.0.210:50611-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: reading length: EOF

[OJHKK] 13:38:44 INFO: Established secure connection to RTF2535- at 192.168.0.210:50617-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

[OJHKK] 13:38:44 INFO: Device RTF2535- client is “syncthing v1.5.0” named “Backup Server” at 192.168.0.210:50617-:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256

So if i’m reading this, the receiving pc (mine) closed the connection, not the remote end. However nothing did, no input from me, it just stops.

It might be, but the PC should also log why it’s doing that. Changing any folder setting requires a reconnect for example.

Given you are selectively picking some lines that you think are relevant, it’s hard for us to tell.

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