Syncthing 2.0.0-beta.11

terry · April 5, 2025, 8:17am

The 2nd attempt is looking better. The logs show the migration took 2hr 40 mins to complete and everything is running.

Index v2 is 21Gb, Wal is 30.4Gb, ram 1.3Gb

So the errors I had are likely due to me going back to v1 in order to do a comparison

Only thing that jumps out is this

Lots of out of sync items, but the folder for the device says it’s up to date. Could it be due to the checkpoint returning 1 / large wal?

[RTF25] 2025/04/05 09:15:01.578844 api.go:768: INFO: Enabled debug data for “sqlite”

[RTF25] 2025/04/05 09:15:09.318519 db_update.go:596: DEBUG: checkpoint at 317089 returned 1 7843440 4116267

[RTF25] 2025/04/05 09:15:23.825640 db_update.go:596: DEBUG: checkpoint at 279376 returned 1 7847506 4116267

[RTF25] 2025/04/05 09:15:33.989247 db_update.go:596: DEBUG: checkpoint at 325722 returned 1 7851197 4116267

[RTF25] 2025/04/05 09:15:44.022786 db_update.go:596: DEBUG: checkpoint at 303074 returned 1 7855089 4116267

[RTF25] 2025/04/05 09:15:52.090392 db_update.go:596: DEBUG: checkpoint at 261479 returned 1 7859069 4116267

[RTF25] 2025/04/05 09:16:00.191752 db_update.go:596: DEBUG: checkpoint at 308067 returned 1 7865266 4116267

EDIT

it’s broken. wal is getting larger, all the checkpoints are now returning 1

239 · April 5, 2025, 11:28am

Same duplication, both instances with clean db on the same host syncing on tmpfs. It happens only when WTXPS renames/deletes but I don’t get why…

WTXPS

[start] 11:27:34 INFO: syncthing v2.0.0-beta.5 "Hafnium Hornet" (go1.24.2 linux-amd64) builder@github.syncthing.net 2025-04-04 17:05:08 UTC
[WTXPS] 11:27:34 INFO: My ID: WTXPS3T-23X2EIJ-WQWBVMZ-ESFCULR-6VSUJWL-23RRHAJ-J4AIUZV-WGL74AR
[WTXPS] 11:27:34 INFO: Hashing performance is 1988.92 MB/s
[WTXPS] 11:27:34 INFO: Overall send rate is unlimited, receive rate is unlimited
[WTXPS] 11:27:34 INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[WTXPS] 11:27:34 INFO: Using discovery mechanism: global discovery server https://discovery-lookup.syncthing.net/v2/?noannounce
[WTXPS] 11:27:34 INFO: Using discovery mechanism: global discovery server https://discovery-announce-v4.syncthing.net/v2/?nolookup
[WTXPS] 11:27:34 INFO: Using discovery mechanism: global discovery server https://discovery-announce-v6.syncthing.net/v2/?nolookup
2025/04/05 11:27:34 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 416 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details.
[WTXPS] 11:27:34 INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027
[WTXPS] 11:27:34 INFO: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]:21027
[WTXPS] 11:27:34 INFO: Ready to synchronize isyte-3rpjy (sendreceive)
[WTXPS] 11:27:34 INFO: QUIC listener ([::]:34563) starting
[WTXPS] 11:27:34 INFO: TCP listener ([::]:34563) starting
[WTXPS] 11:27:34 INFO: GUI and API listening on 127.0.0.1:18384
[WTXPS] 11:27:34 INFO: Access the GUI via the following URL: http://127.0.0.1:18384/
[WTXPS] 11:27:34 INFO: My name is "WTXPS3T"
[WTXPS] 11:27:34 INFO: Device 5WDSW75-NOWTJSQ-STUJRCB-KFFMVU5-EZYGU2X-I7RCK3C-JR6PWKA-CZPYTAU is "5WDSW75" at [dynamic]
[WTXPS] 11:27:34 INFO: Completed initial scan of sendreceive folder isyte-3rpjy
[WTXPS] 11:27:37 INFO: Established secure connection to 5WDSW75 at 192.168.0.171:34563-192.168.0.171:46529/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU608DSE4FVFUV0UM
[WTXPS] 11:27:37 INFO: Device 5WDSW75 client is "syncthing v2.0.0-beta.5" named "5WDSW75" at 192.168.0.171:34563-192.168.0.171:46529/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU608DSE4FVFUV0UM
[WTXPS] 11:27:46 INFO: Joined relay relay://62.84.176.100:22067
[WTXPS] 2025/04/05 11:27:49.275204 api.go:768: INFO: Enabled debug data for "scanner"
[WTXPS] 2025/04/05 11:27:50.025027 api.go:768: INFO: Enabled debug data for "sqlite"
[WTXPS] 2025/04/05 11:27:55.898537 quic_listen.go:59: INFO: quic://0.0.0.0:34563 detected NAT type: Port restricted NAT
[WTXPS] 2025/04/05 11:27:55.898582 quic_listen.go:78: INFO: quic://0.0.0.0:34563 resolved external address quic://95.223.77.240:62053 (via stun.internetcalls.com:3478)
[WTXPS] 2025/04/05 11:27:59.035373 api.go:768: INFO: Enabled debug data for "walkfs"
[WTXPS] 2025/04/05 11:27:59.762252 api.go:768: INFO: Enabled debug data for "watchaggregator"
[WTXPS] 2025/04/05 11:28:14.855121 service.go:314: INFO: Failed to acquire [::]:34563/TCP open port on NAT-PMP@192.168.0.1: getting new lease on NAT-PMP@192.168.0.1 (external port 9731 -> internal port 34563): read udp 192.168.0.171:45166->192.168.0.1:5351: recvfrom: connection refused
[WTXPS] 2025/04/05 11:28:14.855147 service.go:104: INFO: Detected 1 NAT service
[WTXPS] 2025/04/05 11:28:37.490597 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 0
[WTXPS] 2025/04/05 11:28:37.490699 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:28:37.490766 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:29:01.074902 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type non-remove): 1
[WTXPS] 2025/04/05 11:29:01.074930 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[WTXPS] 2025/04/05 11:29:01.074946 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type remove): 2
[WTXPS] 2025/04/05 11:29:11.075303 aggregator.go:347: DEBUG: aggregator/isyte-3rpjy: Notifying about 2 fs events
[WTXPS] 2025/04/05 11:29:11.075585 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 Walk [1] Matcher/[]@0xc0002be6c0
[WTXPS] 2025/04/05 11:29:11.076235 walk.go:457: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 checking: File{Name:"1", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{WTXPS3T 1743845351} {5WDSW75 1743845204}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:01.073065009 +0200 CEST}
[WTXPS] 2025/04/05 11:29:11.076283 walk.go:481: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 rescan: File{Name:"1", Sequence:42, Permissions:0644, ModTime:2025-04-05 11:26:44.323667707 +0200 CEST, Version:{[{WTXPS3T 1743845351} {5WDSW75 1743845204}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:1970-01-01 01:00:00 +0100 CET}
[WTXPS] 2025/04/05 11:29:11.076320 walk.go:484: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 to hash: 1 File{Name:"1", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{WTXPS3T 1743845351} {5WDSW75 1743845204}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:01.073065009 +0200 CEST}
[WTXPS] 2025/04/05 11:29:11.076356 walk.go:208: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 real to hash: 1
[WTXPS] 2025/04/05 11:29:11.076435 blockqueue.go:105: DEBUG: started hashing: File{Name:"1", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{WTXPS3T 1743845351} {5WDSW75 1743845204}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:01.073065009 +0200 CEST}
[WTXPS] 2025/04/05 11:29:11.415235 blockqueue.go:129: DEBUG: completed hashing: File{Name:"1", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{WTXPS3T 1743845351} {5WDSW75 1743845204}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:1024, BlocksHash:3067f2f5e7309710f4c2a933da7dfaf6205d92a430d4df9284974bfcf020bb48, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:01.073065009 +0200 CEST}
[WTXPS] 2025/04/05 11:29:11.415263 walk.go:181: DEBUG: walker/isyte-3rpjy@0xc0001c8f20: Walk isyte-3rpjy [1] current progress 536847476/536847477 at 0.0 MiB/s (99%)
[WTXPS] 2025/04/05 11:29:11.415272 walk.go:196: DEBUG: walker/isyte-3rpjy@0xc0001c8f20 Walk progress done isyte-3rpjy [1] Matcher/[]@0xc0002be6c0
[WTXPS] 2025/04/05 11:29:11.423327 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc0001c8fd0 Walk [2] Matcher/[]@0xc0002be6c0
[WTXPS] 2025/04/05 11:29:11.423342 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[WTXPS] 2025/04/05 11:29:11.424595 blockqueue.go:22: DEBUG: open: open /tmp/isyte-1/.syncthing.2.tmp: no such file or directory
[WTXPS] 2025/04/05 11:29:12.081821 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:29:12.081875 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:29:21.425798 aggregator.go:323: DEBUG: aggregator/isyte-3rpjy: No tracked events, waiting for new event.
[WTXPS] 2025/04/05 11:29:31.828873 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type remove): 2
[WTXPS] 2025/04/05 11:29:31.828898 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[WTXPS] 2025/04/05 11:29:41.832226 aggregator.go:347: DEBUG: aggregator/isyte-3rpjy: Notifying about 1 fs events
[WTXPS] 2025/04/05 11:29:41.832287 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[WTXPS] 2025/04/05 11:29:41.832716 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc00069c000 Walk [2] Matcher/[]@0xc0002be6c0
[WTXPS] 2025/04/05 11:29:41.838834 blockqueue.go:22: DEBUG: open: open /tmp/isyte-1/.syncthing.2.tmp: no such file or directory
[WTXPS] 2025/04/05 11:29:42.351045 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:29:42.351106 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:29:51.835020 aggregator.go:323: DEBUG: aggregator/isyte-3rpjy: No tracked events, waiting for new event.
[WTXPS] 2025/04/05 11:30:12.015019 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 2
[WTXPS] 2025/04/05 11:30:12.015084 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 0
[WTXPS] 2025/04/05 11:30:12.015116 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 0
[WTXPS] 2025/04/05 11:30:12.263812 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 1
[WTXPS] 2025/04/05 11:30:16.301492 model.go:1921: INFO: Lost primary connection to 5WDSW75 at 192.168.0.171:34563-192.168.0.171:46529/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU608DSE4FVFUV0UM: reading length: EOF (0 remain)
[WTXPS] 2025/04/05 11:30:16.301523 model.go:1924: INFO: Connection to 5WDSW75 at 192.168.0.171:34563-192.168.0.171:46529/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU608DSE4FVFUV0UM closed: reading length: EOF
[WTXPS] 2025/04/05 11:30:18.904674 aggregator.go:176: DEBUG: aggregator/isyte-3rpjy: Stopped
[WTXPS] 2025/04/05 11:30:18.904731 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) shutting down
[WTXPS] 2025/04/05 11:30:18.904768 quic_listen.go:150: INFO: QUIC listener ([::]:34563) shutting down
[WTXPS] 2025/04/05 11:30:18.995617 tcp_listen.go:120: INFO: TCP listener ([::]:34563) shutting down
[WTXPS] 2025/04/05 11:30:19.006347 syncthing.go:344: INFO: Exiting

5WDSW

[start] 11:27:37 INFO: syncthing v2.0.0-beta.5 "Hafnium Hornet" (go1.24.2 linux-amd64) builder@github.syncthing.net 2025-04-04 17:05:08 UTC
[5WDSW] 11:27:37 INFO: My ID: 5WDSW75-NOWTJSQ-STUJRCB-KFFMVU5-EZYGU2X-I7RCK3C-JR6PWKA-CZPYTAU
[5WDSW] 11:27:37 INFO: Hashing performance is 1773.47 MB/s
[5WDSW] 11:27:37 INFO: Overall send rate is unlimited, receive rate is unlimited
[5WDSW] 11:27:37 INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
[5WDSW] 11:27:37 INFO: Using discovery mechanism: global discovery server https://discovery-lookup.syncthing.net/v2/?noannounce
[5WDSW] 11:27:37 INFO: Using discovery mechanism: global discovery server https://discovery-announce-v4.syncthing.net/v2/?nolookup
[5WDSW] 11:27:37 INFO: Using discovery mechanism: global discovery server https://discovery-announce-v6.syncthing.net/v2/?nolookup
[5WDSW] 11:27:37 INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027
[5WDSW] 11:27:37 INFO: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]:21027
2025/04/05 11:27:37 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 416 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details.
[5WDSW] 11:27:37 INFO: Ready to synchronize isyte-3rpjy (sendreceive)
[5WDSW] 11:27:37 INFO: TCP listener ([::]:46529) starting
[5WDSW] 11:27:37 INFO: QUIC listener ([::]:46529) starting
[5WDSW] 11:27:37 INFO: GUI and API listening on 127.0.0.1:28384
[5WDSW] 11:27:37 INFO: Access the GUI via the following URL: http://127.0.0.1:28384/
[5WDSW] 11:27:37 INFO: My name is "5WDSW75"
[5WDSW] 11:27:37 INFO: Device WTXPS3T-23X2EIJ-WQWBVMZ-ESFCULR-6VSUJWL-23RRHAJ-J4AIUZV-WGL74AR is "WTXPS3T" at [dynamic]
[5WDSW] 11:27:37 INFO: Completed initial scan of sendreceive folder isyte-3rpjy
[5WDSW] 11:27:37 INFO: Established secure connection to WTXPS3T at 192.168.0.171:46529-192.168.0.171:34563/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU60E0L8M75QD05G4
[5WDSW] 11:27:37 INFO: Device WTXPS3T client is "syncthing v2.0.0-beta.5" named "WTXPS3T" at 192.168.0.171:46529-192.168.0.171:34563/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU60E0L8M75QD05G4
[5WDSW] 11:27:49 INFO: Joined relay relay://191.96.11.38:22067
[5WDSW] 11:27:56 INFO: quic://0.0.0.0:46529 detected NAT type: Port restricted NAT
[5WDSW] 11:27:56 INFO: quic://0.0.0.0:46529 resolved external address quic://95.223.77.240:62045 (via stun.sipgate.net:3478)
[5WDSW] 2025/04/05 11:28:08.752002 api.go:768: INFO: Enabled debug data for "scanner"
[5WDSW] 2025/04/05 11:28:09.149523 api.go:768: INFO: Enabled debug data for "sqlite"
[5WDSW] 2025/04/05 11:28:10.012007 api.go:768: INFO: Enabled debug data for "walkfs"
[5WDSW] 2025/04/05 11:28:10.387909 api.go:768: INFO: Enabled debug data for "watchaggregator"
[5WDSW] 2025/04/05 11:28:19.923884 service.go:314: INFO: Failed to acquire [::]:46529/TCP open port on NAT-PMP@192.168.0.1: getting new lease on NAT-PMP@192.168.0.1 (external port 4378 -> internal port 46529): read udp 192.168.0.171:37578->192.168.0.1:5351: recvfrom: connection refused
[5WDSW] 2025/04/05 11:28:19.923932 service.go:104: INFO: Detected 1 NAT service
[5WDSW] 2025/04/05 11:28:24.911206 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type non-remove): 2
[5WDSW] 2025/04/05 11:28:24.911231 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[5WDSW] 2025/04/05 11:28:24.911241 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type remove): 0
[5WDSW] 2025/04/05 11:28:34.911565 aggregator.go:347: DEBUG: aggregator/isyte-3rpjy: Notifying about 2 fs events
[5WDSW] 2025/04/05 11:28:34.911826 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc000480b00 Walk [2] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:28:34.917208 walk.go:457: DEBUG: walker/isyte-3rpjy@0xc000480b00 checking: File{Name:"2", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845314}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:28:24.910412768 +0200 CEST}
[5WDSW] 2025/04/05 11:28:34.917248 walk.go:481: DEBUG: walker/isyte-3rpjy@0xc000480b00 rescan: File{Name:"2", Sequence:36, Permissions:0644, ModTime:2025-04-05 11:25:04.323667707 +0200 CEST, Version:{[{5WDSW75 1743845314}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:24:03.909222639 +0200 CEST}
[5WDSW] 2025/04/05 11:28:34.917270 walk.go:484: DEBUG: walker/isyte-3rpjy@0xc000480b00 to hash: 2 File{Name:"2", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845314}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:28:24.910412768 +0200 CEST}
[5WDSW] 2025/04/05 11:28:34.917320 walk.go:208: DEBUG: walker/isyte-3rpjy@0xc000480b00 real to hash: 2
[5WDSW] 2025/04/05 11:28:34.917381 blockqueue.go:105: DEBUG: started hashing: File{Name:"2", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845314}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:28:24.910412768 +0200 CEST}
[5WDSW] 2025/04/05 11:28:36.918183 walk.go:181: DEBUG: walker/isyte-3rpjy@0xc000480b00: Walk isyte-3rpjy [2] current progress 341311488/536847477 at 0.0 MiB/s (63%)
[5WDSW] 2025/04/05 11:28:37.473620 blockqueue.go:129: DEBUG: completed hashing: File{Name:"2", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845314}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:1024, BlocksHash:3067f2f5e7309710f4c2a933da7dfaf6205d92a430d4df9284974bfcf020bb48, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:28:24.910412768 +0200 CEST}
[5WDSW] 2025/04/05 11:28:37.473653 walk.go:181: DEBUG: walker/isyte-3rpjy@0xc000480b00: Walk isyte-3rpjy [2] current progress 536847476/536847477 at 0.0 MiB/s (99%)
[5WDSW] 2025/04/05 11:28:37.473667 walk.go:196: DEBUG: walker/isyte-3rpjy@0xc000480b00 Walk progress done isyte-3rpjy [2] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:28:37.485169 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 7.426390457s
[5WDSW] 2025/04/05 11:28:37.485256 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc00047c370 Walk [0] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:28:44.912506 aggregator.go:323: DEBUG: aggregator/isyte-3rpjy: No tracked events, waiting for new event.
[5WDSW] 2025/04/05 11:29:11.426740 blockqueue.go:22: DEBUG: open: open /tmp/isyte-2/.syncthing.1.tmp: no such file or directory
[5WDSW] 2025/04/05 11:29:13.116581 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 1
[5WDSW] 2025/04/05 11:29:13.116678 aggregator.go:188: DEBUG: aggregator/isyte-3rpjy: Skipping path we modified: 1
[5WDSW] 2025/04/05 11:29:51.671485 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type remove): 2
[5WDSW] 2025/04/05 11:29:51.671516 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[5WDSW] 2025/04/05 11:29:57.030491 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type non-remove): 0
[5WDSW] 2025/04/05 11:29:57.030513 aggregator.go:296: DEBUG: aggregator/isyte-3rpjy: Tracking (type remove): 1
[5WDSW] 2025/04/05 11:30:01.675047 aggregator.go:334: DEBUG: aggregator/isyte-3rpjy: No old fs events
[5WDSW] 2025/04/05 11:30:01.675090 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[5WDSW] 2025/04/05 11:30:11.679058 aggregator.go:347: DEBUG: aggregator/isyte-3rpjy: Notifying about 3 fs events
[5WDSW] 2025/04/05 11:30:11.679286 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc0004bc000 Walk [0] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:30:11.679904 walk.go:457: DEBUG: walker/isyte-3rpjy@0xc0004bc000 checking: File{Name:"0", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845411}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:57.029554605 +0200 CEST}
[5WDSW] 2025/04/05 11:30:11.679943 walk.go:481: DEBUG: walker/isyte-3rpjy@0xc0004bc000 rescan: File{Name:"0", Sequence:45, Permissions:0644, ModTime:2025-04-05 11:28:37.323667707 +0200 CEST, Version:{[{5WDSW75 1743845411}]}, VersionHash:, Length:0, Deleted:true, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:26:39.542517314 +0200 CEST}
[5WDSW] 2025/04/05 11:30:11.679964 walk.go:484: DEBUG: walker/isyte-3rpjy@0xc0004bc000 to hash: 0 File{Name:"0", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845411}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:57.029554605 +0200 CEST}
[5WDSW] 2025/04/05 11:30:11.680059 walk.go:208: DEBUG: walker/isyte-3rpjy@0xc0004bc000 real to hash: 0
[5WDSW] 2025/04/05 11:30:11.680152 blockqueue.go:105: DEBUG: started hashing: File{Name:"0", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845411}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:0, BlocksHash:, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:57.029554605 +0200 CEST}
[5WDSW] 2025/04/05 11:30:12.002549 blockqueue.go:129: DEBUG: completed hashing: File{Name:"0", Sequence:0, Permissions:0644, ModTime:2025-04-05 11:15:12.323667707 +0200 CEST, Version:{[{5WDSW75 1743845411}]}, VersionHash:, Length:536847476, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:524288, NumBlocks:1024, BlocksHash:3067f2f5e7309710f4c2a933da7dfaf6205d92a430d4df9284974bfcf020bb48, Platform:{<nil> <nil> <nil> <nil> <nil> <nil>}, InodeChangeTime:2025-04-05 11:29:57.029554605 +0200 CEST}
[5WDSW] 2025/04/05 11:30:12.002587 walk.go:181: DEBUG: walker/isyte-3rpjy@0xc0004bc000: Walk isyte-3rpjy [0] current progress 536847476/536847477 at 0.0 MiB/s (99%)
[5WDSW] 2025/04/05 11:30:12.002595 walk.go:196: DEBUG: walker/isyte-3rpjy@0xc0004bc000 Walk progress done isyte-3rpjy [0] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:30:12.010864 aggregator.go:315: DEBUG: aggregator/isyte-3rpjy: Resetting notifyTimer to 10s
[5WDSW] 2025/04/05 11:30:12.010896 walk.go:125: DEBUG: walker/isyte-3rpjy@0xc0001c88f0 Walk [1 2] Matcher/[]@0xc0002da090
[5WDSW] 2025/04/05 11:30:16.300887 aggregator.go:176: DEBUG: aggregator/isyte-3rpjy: Stopped
[5WDSW] 2025/04/05 11:30:16.300928 quic_listen.go:150: INFO: QUIC listener ([::]:46529) shutting down
[5WDSW] 2025/04/05 11:30:16.301066 relay_listen.go:65: INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) shutting down
[5WDSW] 2025/04/05 11:30:16.301258 model.go:1921: INFO: Lost primary connection to WTXPS3T at 192.168.0.171:46529-192.168.0.171:34563/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU60E0L8M75QD05G4: Syncthing is being stopped (0 remain)
[5WDSW] 2025/04/05 11:30:16.301272 model.go:1924: INFO: Connection to WTXPS3T at 192.168.0.171:46529-192.168.0.171:34563/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256/LAN-P10-61JC82SS5HU60E0L8M75QD05G4 closed: Syncthing is being stopped
[5WDSW] 2025/04/05 11:30:16.302817 tcp_listen.go:120: INFO: TCP listener ([::]:46529) shutting down
[5WDSW] 2025/04/05 11:30:16.310879 syncthing.go:344: INFO: Exiting

calmh · April 5, 2025, 11:45am

All folders are syncing, so a lot of things going on.

Edit: in your latest support bundle, what is going is that several folders are running the last phase of scanning, which is a database walk to look for deleted files. That takes a while…

This whole “can’t iterate over database things while doing something else” is a somewhat annoying limitation. I suspect we’ll end up with some best effort solution, but when there are a lot of folders doing different things at the same time we might need to accept that the wal file grows.

The alternative is to effectively buffer everything in ram which is usually worse (ram being smaller than disk).

You can also prevent this by setting a lower folder concurrency.

Conflicts or filesystem shenanigans is my guess, run with STTRACE=model

bt90 · April 5, 2025, 12:11pm

Or something between 1.29.4 and HEAD.

imsodin · April 5, 2025, 1:05pm

Random thought - I still haven’t properly looked into sqlite/2.0, so this might be entirely irrelevant in the new setup and generally take it with a bag of salt: I remember someone early on mentioning that it’s a typical trap to only use a single database (file) for an entire application with sqlite. Maybe it would be worth considering having separate DBs per folder.
The obvious tradeoff is losing transactionality for anything involving more than one folder. However I don’t think there is much there, if anything. From memory/quick look at old db code it’s only the block list and the block map. Resp. looking at the block map, it seems to be per folder as well, we just use it for a bunch (all?) folders during pulling. It should be ok not to have transactionality here, neither a false block miss (not great, but only performance) nor a false block positive (we verify it) seems problematic.
Block list as it was before would be fine, as we don’t delete entries there under normal operations, only on regular garbage collection. However with my lack of knowledge of the new setup, I can’t say if it’s reasonably doable there (separate DB for block lists, append-only except regular cleanups) - seems concievable, but things always seem concievable if you aren’t in the weeds.

Off-topic musings about (not) keeping up with this on my end.

I still hope to jump on the sqlite/2.0 train soon-ish, it looks amazing and I'd very much like to be fully onboard, as in understand it, and also contribute some. However right now and the foreseeable future (weeks) I unfortunately have close to zero capacity for personal reasons. Just too many things going where it's not even a question to prioritize syncthing - hopefully in a few weeks the question of priorisation comes into play :) I already failed to keep up with Syncthing before the 2.0 push started, and that push is great, and a lot :) Really happy to see this much energy by Jakob and improvements for syncthing, as well as the usual great involvement from everyone in the community. I just wish I could be a bigger part right now :)

calmh · April 5, 2025, 5:06pm

Yes I think we are headed there, or splitting along other boundaries. I have ideas for solutions to most of these problems, just need to get them down.

chaos · April 5, 2025, 7:03pm

A question about splitting DBs per folder. Please correct me if I have this wrong: My understanding is that v1.29.x has a single DB, and can re-use file blocks from any folder to any folder. With a one DB per folder, would this no longer be possible?

calmh · April 5, 2025, 7:17pm

It will be possible, but more annoying for me to implement. It will also lead to a certain amount of duplication and compounded inefficiencies, so the sum total size of all the databases will likely be larger than a single one would be.

terry · April 5, 2025, 11:20pm

On systems with the DBs on HDDs, could that cause fragmentation thus slower access times?

bt90 · April 6, 2025, 5:57am

I think it’s the other way round. With all folders sharing a database file, you have the database rows from different folders scattered throughout the file. The “all folders getting pulled” scenario would thrash the disk in both cases though.

calmh · April 6, 2025, 6:36am

It also enables potential future tweaks like storing the database in the folder, which can be advantageous in some cases. (I’m not going to support this day 1, but it’s a possibility.)

tomasz86 · April 6, 2025, 12:01pm

Are the per-folder database files going to be stored in a single parent folder (e.g. named index-v2.db, similarly to the old index-v0.14.0.db)?

I’m asking, because in the current iteration of Syncthing v2, the single database file is placed directly inside the Syncthing home folder. While this is fine when the database is just a single file (plus one temporary SHM and WAL file), it’s going to be messy when each of these are created per folder. This is especially so because, for example on Windows by default, both the database and the config with keys and certificates are all stored under the same path.

calmh · April 6, 2025, 1:49pm

jb@jbo2:..on Support/Syncthing % ls -l
total 80
-rw-r--r--@  1 jb  staff    794 Aug 21  2024 cert.pem
-rw-------@  1 jb  staff  21703 Apr  4 09:27 config.xml
-rw-r--r--@  1 jb  staff    798 Aug 21  2024 https-cert.pem
-rw-------@  1 jb  staff    288 Aug 21  2024 https-key.pem
drwx------@ 26 jb  staff    832 Apr  6 09:50 index-v2/
-rw-------@  1 jb  staff    288 Aug 21  2024 key.pem
jb@jbo2:..on Support/Syncthing % ls -l index-v2
total 1760824
-rw-r--r--@ 1 jb  staff     770048 Apr  6 09:50 folder.0001.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0001.db-shm
-rw-r--r--@ 1 jb  staff     292552 Apr  6 11:49 folder.0001.db-wal
-rw-r--r--@ 1 jb  staff  135110656 Apr  6 11:30 folder.0002.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0002.db-shm
-rw-r--r--@ 1 jb  staff    4313672 Apr  6 11:49 folder.0002.db-wal
-rw-r--r--@ 1 jb  staff   41750528 Apr  6 11:40 folder.0003.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0003.db-shm
-rw-r--r--@ 1 jb  staff    5442552 Apr  6 15:15 folder.0003.db-wal
-rw-r--r--@ 1 jb  staff   93028352 Apr  6 11:51 folder.0004.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0004.db-shm
-rw-r--r--@ 1 jb  staff    4396072 Apr  6 11:51 folder.0004.db-wal
-rw-r--r--@ 1 jb  staff   32591872 Apr  6 11:47 folder.0005.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0005.db-shm
-rw-r--r--@ 1 jb  staff    4387832 Apr  6 11:49 folder.0005.db-wal
-rw-r--r--@ 1 jb  staff   63721472 Apr  6 11:51 folder.0006.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 folder.0006.db-shm
-rw-r--r--@ 1 jb  staff    4589712 Apr  6 11:52 folder.0006.db-wal
-rw-r--r--@ 1 jb  staff  466067456 Apr  6 13:40 folder.0007.db
-rw-r--r--@ 1 jb  staff      65536 Apr  6 13:39 folder.0007.db-shm
-rw-r--r--@ 1 jb  staff    8388608 Apr  6 13:40 folder.0007.db-wal
-rw-r--r--@ 1 jb  staff      32768 Apr  6 09:50 main.db
-rw-r--r--@ 1 jb  staff      32768 Apr  6 13:39 main.db-shm
-rw-r--r--@ 1 jb  staff    2224832 Apr  6 15:48 main.db-wal
jb@jbo2:..on Support/Syncthing %

AudriusButkevicius · April 6, 2025, 2:10pm

Folders based on indexes sounds scary?

Fingers crossed people don’t fiddle with ordering.

bt90 · April 6, 2025, 3:26pm

The folder numbers are derived from the primary key in the main DB. But it would be cool to have the folder name as an ASCII-fied suffix in the filename. e.g. folder.0001.ceqta-nnvyd.db

tomasz86 · April 6, 2025, 3:32pm

Do you mean the folder ID? The problem is that you are allowed to specify custom IDs, which means that people can put characters in there that aren’t supported by the OS or filesystem .

bt90 · April 6, 2025, 4:48pm

Yeah it’s a can of worms. Autogenerated ones are fine, but you’d have to hunt others through a full UTF8 transliteration to be sure…

calmh · April 6, 2025, 5:00pm

Yeah, ../../../../../etc/passwd and \\192.168.0.1\C$\WINDOWS\SYSTEM32 are totally valid folder IDs.

bt90 · April 6, 2025, 5:22pm

Could we log the folder → DB mapping during startup? My only concern is that we might want to know which folder a DB belongs to while providing support and I don’t see average users doing sqlite queries.

chaos · April 6, 2025, 7:28pm

Perhaps even have the mapping between folder and DB available in the GUI?