Hi. I’ve two Linux servers running ST 1.22 monitoring 4 folders on ext4.
I have a doubt about a sync delay I’m getting, which may range from 1 to up to 10 minutes in rare occasions (customer reported).
In some quick tests I made, I managed to get hosts aligned usually quick, but often after at least 60s. One situation I monitored was the deletion of a file, which was propagated after one minute.
In the log below, I deleted the file prova.093550
at 09:42:51, but the change has been synced to remotes at 09:43:59.
I still don’t know much about ST insights, so it might be considered normal. In that case, I wonder if there are settings which can lower this gap. And yet, if this is normal, I wonder how can I track what customer reported, files which are synced nearly 10 minutes later. Are model and watchaggregator debuggers enough to sort it out? If it’s a network issue?
Thanks
nov 09 09:42:49 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:49.379954 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:42:49 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:49.380016 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:42:51 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:51.476411 aggregator.go:296: DEBUG: aggregator/dati-cl: Tracking (type remove): prova.093550
nov 09 09:42:53 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:53.184298 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:42:53 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:53.184347 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:42:57 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:57.066463 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:42:57 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:57.066557 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:42:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:59.381095 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:42:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:42:59.381156 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:03 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:03.184705 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:03 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:03.184781 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:07 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:07.066671 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:07 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:07.066757 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:09 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:09.381496 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:43:09 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:09.381543 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:13 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:13.185005 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:13 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:13.185070 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:17 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:17.067480 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:17 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:17.067528 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:19 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:19.381946 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:43:19 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:19.381993 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:23 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:23.185144 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:23 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:23.185205 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:27 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:27.068112 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:27 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:27.068176 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:29 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:29.382289 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:43:29 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:29.382344 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:33 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:33.186288 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:33 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:33.186335 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:37 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:37.069103 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:37 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:37.069151 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:39 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:39.382474 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:43:39 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:39.382542 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:43 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:43.186974 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:43 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:43.187032 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:47 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:47.069320 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:47 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:47.069384 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:49 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:49.382652 aggregator.go:334: DEBUG: aggregator/dati-cl: No old fs events
nov 09 09:43:49 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:49.382715 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:53 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:53.187380 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:43:53 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:53.187466 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s
nov 09 09:43:57 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:57.069916 aggregator.go:334: DEBUG: aggregator/dati-ncdata: No old fs events
nov 09 09:43:57 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:57.069965 aggregator.go:315: DEBUG: aggregator/dati-ncdata: Resetting notifyTimer to 10s
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.383710 aggregator.go:347: DEBUG: aggregator/dati-cl: Notifying about 1 fs events
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.383761 aggregator.go:315: DEBUG: aggregator/dati-cl: Resetting notifyTimer to 10s
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.383824 folder.go:218: DEBUG: sendreceive/dati-cl@0xc00029e800 Scan due to watcher
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.383852 folder.go:432: DEBUG: sendreceive/dati-cl@0xc00029e800 scanning
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.384393 folder.go:783: DEBUG: marking file as deleted File{Name:"prova.093550", Sequence:7609480, Permissions:0666, ModTime:2022-11-09 09:43:59.271652068 +0100 CET, Version:{[{WKR5X3I 1667983439}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:false, BlockSize:131072, Blocks:[], BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}}
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.384817 folder.go:496: DEBUG: sendreceive/dati-cl@0xc00029e800 finished scanning, detected 1 changes
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.385051 indexhandler.go:231: DEBUG: indexHandler@0xc000037100 for dati-cl to LXHJPLL at 10.8.0.10:22000-192.168.1.207:22000/tcp-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: Sending 1 files (<74 bytes)
nov 09 09:43:59 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:43:59.452168 model.go:1126: DEBUG: Index update (in): LXHJPLL-KCKGP2V-NTFCREJ-ZKEHNGV-6KNFV3F-UTDWCL7-5Z3DSQR-ABCDEFG / "dati-cl": 1 files
nov 09 09:44:01 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:44:01.058007 progressemitter.go:285: DEBUG: progress emitter: bytes completed for dati-cl: 0
nov 09 09:44:01 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:44:01.058188 model.go:925: DEBUG: model@0xc0003eb380 Completion(LXHJPLL-KCKGP2V-NTFCREJ-ZKEHNGV-6KNFV3F-UTDWCL7-5Z3DSQR-ABCDEFG, "dati-cl"): map[completion:100 globalBytes:324115070807 globalItems:671876 needBytes:0 needDeletes:0 needItems:0 remoteState:valid sequence:4995014]
nov 09 09:44:03 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:44:03.188148 aggregator.go:334: DEBUG: aggregator/homes: No old fs events
nov 09 09:44:03 localhost syncthing[1015]: [WKR5X] 2022/11/09 09:44:03.188204 aggregator.go:315: DEBUG: aggregator/homes: Resetting notifyTimer to 10s