The output is from the killed process, not the kill command itself.
Web based Syncthing not showing info
Thanks - my misunderstanding!
At the moment I have Syncthing in a stalled state, but with no logging currently enabled. I presume it’s not possible to start logging in preparation for the SIGQUIT?
If logging currently goes to nowhere, no, I don’t think so.
Ok - thanks. I’ll get it restarted with logging running, and will report back.
Are there any specific STTRACE variables that might be useful for producing a valid output (as far as you can tell with such little information so far… 
)?
I don’t think so. I suspect things are just taking a while due to large database or similar.
Typical - or interesting - since enabling logging, Syncthing hasn’t stalled again yet… Will keep monitoring!
Hello:
A not-very-useful update: Syncthing stalled again today - so I examined the log before and after sending it a SIGQUIT. The last entry was from about 8 hours before I saw it stalled and killed it:
[M45F6] 08:13:57 INFO: Folder "<Folder Name>" (*****-*****) isn't making sync progress - retrying in 1h3m20.10084172s.
I’ll restart and try to gather more information from another unit too…
Before that there must have been more entries with info about items that failed to sync and why.
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