Before that there must have been more entries with info about items that failed to sync and why.
Web based Syncthing not showing info
Hi Simon - thanks for dropping by.
I can provide the full log privately if required, but here are the last ~20 lines of the log file:
[M45F6] 07:16:26 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 07:20:31 INFO: Relay write: tls: use of closed connection
[M45F6] 07:20:31 INFO: Relay write: tls: use of closed connection
[M45F6] 07:20:31 INFO: Disconnected from relay relay://212.237.131.162:443
[M45F6] 07:20:33 INFO: Connection to *******-*******-*******-*******-*******-*******-*******-******* at 192.168.1.4:43306-212.237.131.162:443/relay-server/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 closed: reading length: EOF
[M45F6] 07:20:36 INFO: Joined relay relay://5.9.16.38:22067
[M45F6] 07:20:36 INFO: Established secure connection to *******-*******-*******-*******-*******-*******-*******-******* at [::]:22000-78.141.62.39:56176/quic-client/TLS1.3-TLS_AES_128_GCM_SHA256
[M45F6] 07:20:36 INFO: Device *******-*******-*******-*******-*******-*******-*******-******* client is "syncthing v1.2.1-rc.3" named "**-NAS" at [::]:22000-78.141.62.39:56176/quic-client/TLS1.3-TLS_AES_128_GCM_SHA256
[M45F6] 07:20:37 INFO: Connected to device *******-*******-*******-*******-*******-*******-*******-******* with a newer version (current "v1.2.0" < remote "v1.2.1-rc.3"). Checking for upgrades.
[M45F6] 07:20:37 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 07:23:42 INFO: Connection to *******-*******-*******-*******-*******-*******-*******-******* at 192.168.1.4:44209-217.151.118.241:9398/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 closed: read timeout
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/85F5830D-1035-4AFB-90A2-31178A37E05B.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/559AFB9E-5707-4F19-9180-80616E4A46BC.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/6DD4F7C6-D9F3-4FE7-8678-984BBC925C23.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/8629024B-CBB1-4613-8D1B-711AE7E2D81F.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/36529254-BBDD-497A-B645-6596CF48F956.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/CB445E36-2BBE-48CF-A886-6B314054FF58.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/BF954648-5623-48E5-9D25-C375A8185E21.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/Inst 3_bip.aif"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/8C0B9794-8971-4549-B4B7-57EB1F00D8AD.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/322AE719-F3A5-4BD7-95FF-7B3A4F303578.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/6F904CED-28D8-42B9-BA5E-D335B336C210.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/13F94674-58FD-44F5-97D3-D9C2EADC7A44.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/F33146FE-9D8E-4E43-8A3A-CA9945419846.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/47C05AB6-4B89-4666-9503-AB8D568BD9BB.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/7321F32A-6267-42AE-9365-35463FC98D8D.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/B12F3346-2029-4F6A-8DDE-5F44F126B3F6.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/D5D4F8D6-D055-4EC5-A8C7-8023565A62C9.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/D73ABBD1-EF0C-4A60-9EC8-36147FAAF81A.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/6640205C-4427-4BF2-9464-CF5A50E939CC.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/B759DE01-52C6-44BF-A784-DD3FA13600F7.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/BA033194-F7F5-4454-B51A-B86D775077A8.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/47EFA1A5-1CC3-4ECD-AB9D-E17AB5256365.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/AEC2911D-44F4-4BCA-8591-F135A63FC8CA.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/80BA7399-81A4-43E5-BA95-321C2A1794A0.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/AB305910-7925-419B-9A93-86A25B094031.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/BAFA02E2-66E8-4469-B112-7E5AB57FCED6.undo"): pull: connection closed
[M45F6] 07:23:42 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/BE705F36-8EB7-4027-BB9D-6C7DB4850A1E.undo"): pull: connection closed
[M45F6] 07:24:16 INFO: Established secure connection to *******-*******-*******-*******-*******-*******-*******-******* at 192.168.1.4:44316-217.151.118.241:9398/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
[M45F6] 07:24:16 INFO: Device *******-*******-*******-*******-*******-*******-*******-******* client is "syncthing v1.2.0" named "** Laptop" at 192.168.1.4:44316-217.151.118.241:9398/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
[M45F6] 07:44:50 INFO: Connection to *******-*******-*******-*******-*******-*******-*******-******* at 192.168.1.4:54858-81.103.212.38:24737/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 closed: reading length: read tcp 192.168.1.4:54858->ww.xx.yy.zz:24737: read: connection reset by peer
[M45F6] 07:47:25 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/.dummy"): delete file: stat /volume2/<Folder Name Here>/File/Path/Here: no such file or directory
[M45F6] 07:50:20 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/Autosave/2019-08-02 6:45:17 am +0000.displayData"): pull: no such file
[M45F6] 07:50:40 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/Autosave/2019-08-02 6:45:17 am +0000.eventData"): pull: no such file
[M45F6] 07:50:51 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/Autosave/2019-08-02 6:45:17 am +0000.songData"): pull: no such file
[M45F6] 08:13:57 INFO: Folder "<Folder Name Here>" (*****-*****) isn't making sync progress - retrying in 1h3m20.10084172s.
Hope that’s of some use!
The problem is with the connection to the device at 217.151.118.241, which can be established, but then later fails. It’s not clear what the reason is, UI/logs on that device may contain clues.
Thanks Simon.
I haven’t yet had a chance to investigate on the machine in question (which is a Mac laptop, with seemingly no expected issues otherwise) - but here are a couple more thoughts I’d be grateful for your opinion on:
1 - The NAS Syncthing stalled again - here’s the recent log entries:
[M45F6] 02:30:00 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/020819_1.wav"): no connected device has the required version of this file
[M45F6] 02:30:00 INFO: Puller (folder "<Folder Name Here>" (*****-*****), item "File/Path/Here/020819_2.wav"): no connected device has the required version of this file
[M45F6] 02:35:30 INFO: Listen (BEP/relay): joining session: Incorrect response code 2: already connected
[M45F6] 02:45:50 INFO: Established secure connection to 6FLFQJH-*******-*******-*******-*******-*******-*******-******* at 192.168.1.4:48550-51.15.105.255:22067/relay-server/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
[M45F6] 02:45:50 INFO: Device 6FLFQJH-*******-*******-*******-*******-*******-*******-******* client is "syncthing v1.2.0" named "** Laptop" at 192.168.1.4:48550-51.15.105.255:22067/relay-server/TLS1.2-TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
[M45F6] 07:17:39 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 19:17:39 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 07:17:39 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 19:17:40 INFO: Automatic upgrade: couldn't find a release to download
[M45F6] 05:02:01 INFO: Connection to RS5AKFS-*******-*******-*******-*******-*******-*******-******* at [::]:22000-78.141.62.39:56176/quic-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: writing message: NO_ERROR: No recent network activity
[M45F6] 07:17:44 INFO: Automatic upgrade: couldn't find a release to download
You will see one of the last entries before it seems to stop all non-upgrade activity is where it establishes a connection to the same machine as you suggested the problem was with before…
2 - Will pausing the laptop in Remote Devices on this NAS be sufficient to confirm that there is likely something amiss with the connection between these two devices?
3 - Both these machines are part of a much larger cluster - yet it’s only this system which seems to have an issue with stalling. Might that be expected?
Many thanks!
Seems it’s just like a connection timeout, you should provide logs from both sides.
Hi:
I’ve just managed to capture a SIGQUIT dump whilst this was going on - https://pastebin.com/GjyGhcaS
A couple of notes:
- The last device that was connected to in the logs before everything stopped was another (different) Mac laptop, with no known Syncthing issues;
- Unfortunately the laptops so far implicated aren’t entirely under my control, so it’s going to be difficult to get useful logs from them.
Please let me know if I can provide any other information - thanks!
Tons of interesting stuff there, one that caught my eye:
goroutine 134160 [chan receive, 87 minutes]:
github.com/syncthing/syncthing/lib/protocol.(*rawConnection).internalClose.func1()
/opt/tcagent/syncthing-3-work/174e136266f8a219/lib/protocol/protocol.go:907 +0x1de
sync.(*Once).Do(0xc01df00588, 0xc000051ef0)
/usr/local/go/src/sync/once.go:44 +0xb3
github.com/syncthing/syncthing/lib/protocol.(*rawConnection).internalClose(0xc01df004e0, 0x1026100, 0xc00003f060)
/opt/tcagent/syncthing-3-work/174e136266f8a219/lib/protocol/protocol.go:894 +0x6f
github.com/syncthing/syncthing/lib/protocol.(*rawConnection).pingReceiver(0xc01df004e0)
/opt/tcagent/syncthing-3-work/174e136266f8a219/lib/protocol/protocol.go:953 +0x3bb
created by github.com/syncthing/syncthing/lib/protocol.(*rawConnection).Start
/opt/tcagent/syncthing-3-work/174e136266f8a219/lib/protocol/protocol.go:260 +0xcb
Hi:
Sorry - I don’t understand the dump output, so I don’t know if this is related, or if I should open a new thread - but:
I’m also seeing Syncthing getting killed by the kernel on this same system because it’s using too much RAM. This wasn’t a major issue prior to 1.2.0 - I can see 3 such instances in my kernel log for May/June, but 25 in July/August so far.
Is an increased RAM footprint expected in 1.2.0+? Please let me know if I should fill in more details here, or start a new thread.
Thanks!
Not really, I don’t think anything changed in terms of memory usage and this does not look related.
@Moisie:
https://github.com/syncthing/syncthing/pull/5943 might help with your problem and will bin in v1.2.2 - if you can install the new release candidate that will come out this week and report whether the situation changed, that would be great!
Hi Simon:
Once again, I’m indebted to your helpfulness. Of course, I’ll try the RC and report back!
1 Like
Hi:
I’ve installed v1.2.2-rc.3 on a couple of NAS units in one of my clusters.
Whilst I’ll need to allow them a while to settle in before I can fully get behind it, the initial impression is that this issue does appear to be much improved.
Massive thanks as always to the team.
1 Like
Hello:
An update to this: the NAS units I initially upgraded to v1.2.2-rc.3 are working well - the update appears to have resolved the stalling issue, and the units are working very happily thankyouverymuchindeed. 
As it was working so nicely, I rolled it out to a couple of other NAS units I look after (same NAS model, different cluster). I suspect you’re already aware of this - but these units are panicking quite regularly:
It looks like the panic logs are getting reported - but please let me know if there’s any other information I can provide.
Thanks for reporting back.
They do, and as nothing new has shown up, it’s probably a false positive from the deadlock-detector once again (there are new events for that). That’s only enabled in release candidates, that’s why you didn’t see it before. And given the huge set of data it’s also quite plausible (not saying it’s good though, I’ll probably have a look at the panics and do another round of lock-squashing).
@calmh @AudriusButkevicius Looks like we have two mechanism for deadlock detection: One in lib/sync using go-deadlock and a custom one in lib/model/util.go. The former is controllable by STDEADLOCKTIMEOUT, the latter not in case or RCs. Is there any reason we need a custom deadlock detector over the global one in the model?
They serve different purposes, one just checks for the lock being released often enough, the other one check for locking order consistency.
1 Like
Hi:
Thanks for the feedback.
Ah yes - I remember having to set the STDEADLOCKTIMEOUT before whilst using RCs - had forgotten about that. 
I’m happy to leave it as it is if the panic log reporting is useful for you - but otherwise I’ll set this variable so it runs as ‘normal’.
You can set it, there’s plenty of those 
Maybe you are already aware: You can’t disable it fully on RCs (i.e. set to 0), you can only set a different timeout (which if you set it high enough is more or less disabling it).
Thought so! 
Yes - I’ll set it to 21600 for now - hopefully will give the NAS time to service all its demands… I’ll also throw a fresh shovelful of coal in there…
1 Like
This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.