Hey everyone,
I am really happy with the performance of Syncthing, but I still have a few issues with stability in my scripted distribution system. I sync a build directory during the build time overnight and distribute the folder from one sendonly master to 1-15 receiving sendreceive servers. All devices are fairly powerful and while the master has a high load during the build, the receiving devices have relatively low load.
Sometime the sync to several receivers is stuck with the same amount of files needed to sync on all of them. I still do not understand the issue for this problem and looked into the logs.
I noticed several panic log files on some of the receiving servers, but none on the sending master. I am not sure if those panics are connected to the sync failures I am seeing. Almost all of the panic reports are “Panic: Send on closed channel” which seems to be an exception thrown by Go.
I have sanitized a panic log.
[start] 21:22:26 INFO: Audit log in /PATH/audit-20181023-212226.log
[D7LIW] 21:22:26 INFO: syncthing v0.14.50 "Dysprosium Dragonfly" (go1.11 linux-amd64) teamcity@build.syncthing.net 2018-09-02 19:36:07 UTC
[D7LIW] 21:22:26 INFO: My ID: D7LIWYY-
[D7LIW] 21:22:27 INFO: Single thread SHA256 performance is 304 MB/s using minio/sha256-simd (264 MB/s using crypto/sha256).
[D7LIW] 21:22:27 INFO: Hashing performance is 251.40 MB/s
[D7LIW] 21:22:28 INFO: Ready to synchronize "FOLDER_LABEL" (FOLDER_LABEL) (sendreceive)
[D7LIW] 21:22:28 INFO: Overall send rate is unlimited, receive rate is unlimited
[D7LIW] 21:22:28 INFO: Rate limits do not apply to LAN connections
[D7LIW] 21:22:28 INFO: Using discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX
[D7LIW] 21:22:28 INFO: Using discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX
...
[D7LIW] 21:22:28 INFO: Using discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX
[D7LIW] 21:22:28 INFO: TCP listener ([::]:22000) starting
[D7LIW] 21:22:28 INFO: Device CRGQG6P is "Computer315" at [dynamic]
[D7LIW] 21:22:28 INFO: Device GGGPTPD is "Computer345" at [dynamic]
[D7LIW] 21:22:28 INFO: Device KFRTAH5 is "Computer359" at [dynamic]
[D7LIW] 21:22:28 INFO: Device MELCN72 is "Computer297" at [dynamic]
[D7LIW] 21:22:28 INFO: Device ZTE3QTE is "Computer311" at [dynamic]
[D7LIW] 21:22:28 INFO: Device D7LIWYY is "Computer391" at [dynamic]
[D7LIW] 21:22:28 INFO: Device EI72JDO is "Computer320" at [dynamic]
[D7LIW] 21:22:28 INFO: Device F3CYHJF is "Computer321" at [dynamic]
[D7LIW] 21:22:28 INFO: Device 7I63EFX is "Computer331" at [dynamic]
[D7LIW] 21:22:28 INFO: GUI and API listening on XX.XXX.18.194:8384
[D7LIW] 21:22:28 INFO: Access the GUI via the following URL: http://Computer391:8384/
[D7LIW] 21:22:28 INFO: Established secure connection to CRGQG6P at XX.XXX.18.194:42736-XX.XXX.16.36:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:28 INFO: Device CRGQG6P client is "syncthing v0.14.50" named "Computer315" at XX.XXX.18.194:42736-XX.XXX.16.36:22000/tcp-client
[D7LIW] 21:22:29 INFO: Established secure connection to F3CYHJF at XX.XXX.18.194:37882-XX.XXX.16.42:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:29 INFO: Device F3CYHJF client is "syncthing v0.14.50" named "Computer321" at XX.XXX.18.194:37882-XX.XXX.16.42:22000/tcp-client
[D7LIW] 21:22:30 INFO: Established secure connection to GGGPTPD at XX.XXX.18.194:48762-XX.XXX.19.67:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:30 INFO: Device GGGPTPD client is "syncthing v0.14.50" named "Computer345" at XX.XXX.18.194:48762-XX.XXX.19.67:22000/tcp-client
[D7LIW] 21:22:32 INFO: Established secure connection to EI72JDO at XX.XXX.18.194:22000-XX.XXX.20.13:34884/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:32 INFO: Device EI72JDO client is "syncthing v0.14.50" named "Computer320" at XX.XXX.18.194:22000-XX.XXX.20.13:34884/tcp-server
[D7LIW] 21:22:32 INFO: Failed to exchange Hello messages with EI72JDO at [fefb:75cc%eth0]:22000-[fef8:1689%eth0]:58710/tcp-server: EOF
[D7LIW] 21:22:33 INFO: Established secure connection to MELCN72 at XX.XXX.18.194:22000-XX.XXX.22.239:49154/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:33 INFO: Device MELCN72 client is "syncthing v0.14.50" named "Computer297" at XX.XXX.18.194:22000-XX.XXX.22.239:49154/tcp-server
[D7LIW] 21:22:33 INFO: Connection to CRGQG6P at XX.XXX.18.194:42736-XX.XXX.16.36:22000/tcp-client closed: reading length: read tcp XX.XXX.18.194:42736->XX.XXX.16.36:22000: read: connection reset by peer
[D7LIW] 21:22:34 INFO: Established secure connection to KFRTAH5 at XX.XXX.18.194:53840-XX.XXX.21.17:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:34 INFO: Device KFRTAH5 client is "syncthing v0.14.50" named "Computer359" at XX.XXX.18.194:53840-XX.XXX.21.17:22000/tcp-client
[D7LIW] 21:22:34 INFO: Established secure connection to ZTE3QTE at [fefb:75cc%eth0]:37900-[fef5:56b4%eth0]:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:34 INFO: Device ZTE3QTE client is "syncthing v0.14.50" named "Computer311" at [fefb:75cc%eth0]:37900-[fef5:56b4%eth0]:22000/tcp-client
[D7LIW] 21:22:34 INFO: Established secure connection to 7I63EFX at XX.XXX.18.194:45810-XX.XXX.19.194:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:34 INFO: Device 7I63EFX client is "syncthing v0.14.50" named "Computer331" at XX.XXX.18.194:45810-XX.XXX.19.194:22000/tcp-client
[D7LIW] 21:22:34 INFO: Connection to GGGPTPD at XX.XXX.18.194:48762-XX.XXX.19.67:22000/tcp-client closed: reading length: read tcp XX.XXX.18.194:48762->XX.XXX.19.67:22000: read: connection reset by peer
[D7LIW] 21:22:37 INFO: Established secure connection to CRGQG6P at XX.XXX.18.194:42766-XX.XXX.16.36:22000/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:37 INFO: Device CRGQG6P client is "syncthing v0.14.50" named "Computer315" at XX.XXX.18.194:42766-XX.XXX.16.36:22000/tcp-client
[D7LIW] 21:22:38 INFO: Established secure connection to GGGPTPD at XX.XXX.18.194:22000-XX.XXX.19.67:48912/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:22:38 INFO: Device GGGPTPD client is "syncthing v0.14.50" named "Computer345" at XX.XXX.18.194:22000-XX.XXX.19.67:48912/tcp-server
[D7LIW] 21:22:39 INFO: Detected 0 NAT services
[D7LIW] 21:22:55 INFO: Completed initial scan of sendreceive folder "FOLDER_LABEL" (FOLDER_LABEL)
[D7LIW] 21:23:57 INFO: Connection to 7I63EFX at XX.XXX.18.194:45810-XX.XXX.19.194:22000/tcp-client closed: reading length: read tcp XX.XXX.18.194:45810->XX.XXX.19.194:22000: read: connection reset by peer
[D7LIW] 21:24:15 INFO: Connection to F3CYHJF at XX.XXX.18.194:37882-XX.XXX.16.42:22000/tcp-client closed: reading length: read tcp XX.XXX.18.194:37882->XX.XXX.16.42:22000: read: connection reset by peer
[D7LIW] 21:24:19 INFO: Established secure connection to F3CYHJF at [fefb:75cc%eth0]:22000-[fef8:163d%eth0]:34678/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:24:19 INFO: Device F3CYHJF client is "syncthing v0.14.50" named "Computer321" at [fefb:75cc%eth0]:22000-[fef8:163d%eth0]:34678/tcp-server
[D7LIW] 21:24:20 INFO: Established secure connection to 7I63EFX at [fefb:75cc%eth0]:22000-[fee5:2b12%eth0]:40640/tcp-server (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[D7LIW] 21:24:20 INFO: Device 7I63EFX client is "syncthing v0.14.50" named "Computer331" at [fefb:75cc%eth0]:22000-[fee5:2b12%eth0]:40640/tcp-server
[D7LIW] 21:47:30 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File1"): finisher: pull: peers who had this file went away, or the file has changed while syncing. will retry later
[D7LIW] 21:47:30 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File1"): finisher: pull: peers who had this file went away, or the file has changed while syncing. will retry later
[D7LIW] 23:59:09 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File2"): finisher: file modified but not rescanned; will try again later
[D7LIW] 23:59:09 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File3"): finisher: file modified but not rescanned; will try again later
[D7LIW] 23:59:09 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File3"): finisher: file modified but not rescanned; will try again later
[D7LIW] 00:00:57 INFO: Puller (folder "FOLDER_LABEL" (FOLDER_LABEL), file "File3"): finisher: file modified but not rescanned; will try again later
Panic at 2018-10-24T00:00:57+02:00
panic: send on closed channel
goroutine 604032 [running]:
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).performFinish(0xc00027e840, 0xc0002aa090, 0xc004d8e780, 0xc000a48f00, 0xc000a48d80, 0xe293c0, 0xc000562320)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:1449 +0x7e2
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).finisherRoutine(0xc00027e840, 0xc0002aa090, 0xc000a48ea0, 0xc000a48f00, 0xc000a48d80)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:1510 +0x785
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pullerIteration.func4(0xc00027e840, 0xc0002aa090, 0xc000a48ea0, 0xc000a48f00, 0xc000a48d80, 0xe30020, 0xc004c7c170)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:256 +0x53
created by github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pullerIteration
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:255 +0x521
goroutine 1 [chan receive, 158 minutes]:
main.syncthingMain(0x7fffffffeac4, 0x32, 0x0, 0x0, 0x0, 0x1, 0x7fffffffeb00, 0x40, 0x1, 0x0, ...)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:907 +0x1bad
main.main()
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/cmd/syncthing/main.go:439 +0x340
goroutine 19 [chan receive]:
github.com/syncthing/syncthing/vendor/github.com/syncthing/notify.(*nonrecursiveTree).dispatch(0xc0001603c0, 0xc000160300)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/syncthing/notify/tree_nonrecursive.go:36 +0xb6
created by github.com/syncthing/syncthing/vendor/github.com/syncthing/notify.newNonrecursiveTree
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/syncthing/notify/tree_nonrecursive.go:29 +0xdc
goroutine 20 [chan receive, 1 minutes]:
github.com/syncthing/syncthing/vendor/github.com/syncthing/notify.(*nonrecursiveTree).internal(0xc0001603c0, 0xc000160360)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/syncthing/notify/tree_nonrecursive.go:81 +0x7b
created by github.com/syncthing/syncthing/vendor/github.com/syncthing/notify.newNonrecursiveTree
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/syncthing/notify/tree_nonrecursive.go:30 +0x108
goroutine 114 [syscall, 158 minutes]:
os/signal.signal_recv(0x0)
/usr/local/go/src/runtime/sigqueue.go:139 +0x9c
os/signal.loop()
/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
created by os/signal.init.0
/usr/local/go/src/os/signal/signal_unix.go:29 +0x41
goroutine 605638 [runnable]:
time.Time.MarshalBinary(0xbeec04666c7795aa, 0x8a6a7877cb7, 0x130cae0, 0x40, 0x48, 0xc001a9d180, 0x40, 0x80)
/usr/local/go/src/time/time.go:1147 +0x87
github.com/syncthing/syncthing/lib/db.(*NamespacedKV).PutTime(0xc0011063a0, 0xb76241, 0x8, 0xbeec04666c7795aa, 0x8a6a7877cb7, 0x130cae0)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/db/namespaced.go:79 +0xdf
github.com/syncthing/syncthing/lib/stats.(*DeviceStatisticsReference).WasSeen(0xc0011063c0)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/stats/device.go:45 +0x111
github.com/syncthing/syncthing/lib/model.(*Model).deviceWasSeen(0xc000274360, 0xe4f010ef16b23dfa, 0xc9681dd3bbf42730, 0xf0332f78fda67bef, 0x87efb056c5533fb9)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/model.go:1677 +0x4d
github.com/syncthing/syncthing/lib/model.(*Model).Connection(0xc000274360, 0xe4f010ef16b23dfa, 0xc9681dd3bbf42730, 0xf0332f78fda67bef, 0x87efb056c5533fb9, 0x8, 0x0, 0x0)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/model.go:1472 +0x115
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).processNeeded.func1(0xe36240, 0xc00733ea00, 0xe36240)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:350 +0x765
github.com/syncthing/syncthing/lib/db.nativeFileIterator.func1(0xe36240, 0xc00733e960, 0xc00024ad20)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/db/set.go:344 +0x1d5
github.com/syncthing/syncthing/lib/db.(*Instance).withNeedLocal(0xc00024ad20, 0xc0065efb20, 0x19, 0x20, 0x0, 0xc00011ab80)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/db/leveldb_dbinstance.go:495 +0x375
github.com/syncthing/syncthing/lib/db.(*Instance).withNeed(0xc00024ad20, 0xc0065efb20, 0x19, 0x20, 0xc004342f58, 0x20, 0x20, 0xc004342f00, 0xc00011ab80)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/db/leveldb_dbinstance.go:409 +0xf79
github.com/syncthing/syncthing/lib/db.(*FileSet).WithNeed(0xc00026c3c0, 0xffffffffffffffff, 0xffffffffffffffff, 0xffffffffffffffff, 0xffffffffffffffff, 0xc0053bdd10)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/db/set.go:197 +0x1e6
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).processNeeded(0xc00027e840, 0xc0002aa090, 0xc003fcf920, 0xc003fcf860, 0xc003fcf8c0, 0xc003fcf7a0, 0xc003fcf7a0, 0xe30020, 0xc0007e4630, 0xc003fcf7a0, ...)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:300 +0x23c
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pullerIteration(0xc00027e840, 0xc0002aa090, 0xc003fcf700, 0xc003fcf7a0, 0x2)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:260 +0x573
github.com/syncthing/syncthing/lib/model.(*sendReceiveFolder).pull(0xc00027e840, 0xc004343d00)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder_sendrecv.go:174 +0x4f8
github.com/syncthing/syncthing/lib/model.(*folder).Serve(0xc00027e840)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/lib/model/folder.go:147 +0x79b
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1(0xc0002222a0, 0x4000000000000000, 0x7ffff5b55580, 0xc00027e840)
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:532 +0x67
created by github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService
/opt/tcagent/syncthing-work/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/supervisor.go:522 +0x5b
I can add more lines or look into more panic files if necessary.