[solved] [bep] no start info

Development
1

Hi,

when my app (syncspirit), communicates with syncthing (v1.23.2), syncthing “forgets” download progress.

At the protocol level, my app sends Index message with zero files and non-zero index, and later it sends updates with IndexUpdate. In the UI it shows 100% in sync, however, after my app reconnect it drops to zero.

Here are the logs:


[4QDTF] 2023/03/12 19:27:42.688870 service.go:245: INFO: Peer at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 did not negotiate bep/1.0
[4QDTF] 2023/03/12 19:27:42.692460 service.go:423: INFO: Established secure connection to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
[4QDTF] 2023/03/12 19:27:42.692541 indexhandler.go:463: DEBUG: Removing index handler for device WICHSMT and folder default
[4QDTF] 2023/03/12 19:27:42.692557 indexhandler.go:469: DEBUG: Removed index handler for device WICHSMT and folder default
[4QDTF] 2023/03/12 19:27:42.692600 indexhandler.go:549: DEBUG: Not resuming index handler for device WICHSMT and folder lwmfe-w394s as none is paused and there is no start info
[4QDTF] 2023/03/12 19:27:42.692613 indexhandler.go:463: DEBUG: Removing index handler for device WICHSMT and folder vnsfq-njnvr
[4QDTF] 2023/03/12 19:27:42.692620 indexhandler.go:469: DEBUG: Removed index handler for device WICHSMT and folder vnsfq-njnvr
[4QDTF] 2023/03/12 19:27:42.692654 model.go:2265: INFO: Device WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH client is "syncspirit v0.3.0" named "xps" at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
[4QDTF] 2023/03/12 19:27:42.693314 model.go:1168: DEBUG: Handling ClusterConfig from WICHSMT
[4QDTF] 2023/03/12 19:27:42.693416 indexhandler.go:73: DEBUG: Device WICHSMT folder "trivial-folder" (lwmfe-w394s) has no index ID for us
[4QDTF] 2023/03/12 19:27:42.693452 indexhandler.go:95: INFO: Device WICHSMT folder "trivial-folder" (lwmfe-w394s) has a new index ID (0xE037171556F3CF96)
[4QDTF] 2023/03/12 19:27:42.693659 indexhandler.go:132: DEBUG: Starting index handler for lwmfe-w394s to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 (slv=0)
[4QDTF] 2023/03/12 19:27:42.693897 indexhandler.go:231: DEBUG: indexHandler@0xc0003b8680 for lwmfe-w394s to WICHSMT at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: Sending 1 files (<148 bytes)
[4QDTF] 2023/03/12 19:27:42.694841 model.go:1129: DEBUG: Index (in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH / "lwmfe-w394s": 0 files
[4QDTF] 2023/03/12 19:27:42.736119 model.go:1854: DEBUG: model@0xc000103860 REQ(in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH: "lwmfe-w394s" / "hello.txt" o=0 s=32 t=false
[4QDTF] 2023/03/12 19:27:42.739026 model.go:1129: DEBUG: Index update (in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH / "lwmfe-w394s": 1 files
[4QDTF] 2023/03/12 19:27:43.689547 progressemitter.go:285: DEBUG: progress emitter: bytes completed for lwmfe-w394s: 0
[4QDTF] 2023/03/12 19:27:43.689817 model.go:928: DEBUG: model@0xc000103860 Completion(WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH, "lwmfe-w394s"): map[completion:100 globalBytes:32 globalItems:1 needBytes:0 needDeletes:0 needItems:0 remoteState:valid sequence:2]

I disconnect, and then

[4QDTF] 2023/03/12 19:27:57.283135 model.go:1783: INFO: Connection to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: closed by remote: peer_supervisor actor shutdown has been requested by supervisor <- net::coodinator actor shutdown has been requested by supervisor <- net::coodinator normal shutdown
[4QDTF] 2023/03/12 19:27:57.283378 indexhandler.go:137: DEBUG: Exiting index handler for lwmfe-w394s to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:54171/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256: context canceled
[4QDTF] 2023/03/12 19:28:29.305599 service.go:245: INFO: Peer at 192.168.100.42:22000-192.168.100.42:53755/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 did not negotiate bep/1.0
[4QDTF] 2023/03/12 19:28:29.310028 service.go:423: INFO: Established secure connection to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:53755/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
[4QDTF] 2023/03/12 19:28:29.310103 indexhandler.go:463: DEBUG: Removing index handler for device WICHSMT and folder default
[4QDTF] 2023/03/12 19:28:29.310119 indexhandler.go:469: DEBUG: Removed index handler for device WICHSMT and folder default
[4QDTF] 2023/03/12 19:28:29.310134 indexhandler.go:549: DEBUG: Not resuming index handler for device WICHSMT and folder lwmfe-w394s as none is paused and there is no start info
[4QDTF] 2023/03/12 19:28:29.310146 indexhandler.go:463: DEBUG: Removing index handler for device WICHSMT and folder vnsfq-njnvr
[4QDTF] 2023/03/12 19:28:29.310154 indexhandler.go:469: DEBUG: Removed index handler for device WICHSMT and folder vnsfq-njnvr
[4QDTF] 2023/03/12 19:28:29.310191 model.go:2265: INFO: Device WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH client is "syncspirit v0.3.0" named "xps" at 192.168.100.42:22000-192.168.100.42:53755/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256
[4QDTF] 2023/03/12 19:28:29.311167 model.go:1168: DEBUG: Handling ClusterConfig from WICHSMT
[4QDTF] 2023/03/12 19:28:29.311311 indexhandler.go:62: DEBUG: Device WICHSMT folder "trivial-folder" (lwmfe-w394s) is delta index compatible (mlv=5)
[4QDTF] 2023/03/12 19:28:29.311426 indexhandler.go:132: DEBUG: Starting index handler for lwmfe-w394s to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:53755/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 (slv=5)
[4QDTF] 2023/03/12 19:28:29.352342 model.go:1129: DEBUG: Index (in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH / "lwmfe-w394s": 0 files
[4QDTF] 2023/03/12 19:28:29.749422 progressemitter.go:285: DEBUG: progress emitter: bytes completed for lwmfe-w394s: 0
[4QDTF] 2023/03/12 19:28:29.749889 model.go:928: DEBUG: model@0xc000103860 Completion(WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH, "lwmfe-w394s"): map[completion:0 globalBytes:32 globalItems:1 needBytes:32 needDeletes:0 needItems:1 remoteState:valid sequence:0]

The key log info, imho, is:

[4QDTF] 2023/03/12 19:28:29.310134 indexhandler.go:549: DEBUG: Not resuming index handler for device WICHSMT and folder lwmfe-w394s as none is paused and there is no start info

However, I think I do correctly use bep-proto, and it is valid to send Index with zero-files. Or, may, I did misread something?

I think the same buggy behavior can be achieved, when sharing empty folder, and lately add files in it.

Thanks,

2

That log line looks like it’s still related to the dropped connection. After you send a cluster-config again, the index handler gets started as expected:

[4QDTF] 2023/03/12 19:28:29.311426 indexhandler.go:132: DEBUG: Starting index handler for lwmfe-w394s to WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH at 192.168.100.42:22000-192.168.100.42:53755/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 (slv=5)

What’s the actual issue you are experiencing?

3

before disconnect I get this:

2023-03-12_20-30

However, right after reconnected I get this:

2023-03-12_20-31

4

The issue is you send a index message without any elements, not an index update. Relevant BEP part:

The Index and Index Update messages define the contents of the senders folder. An Index message represents the full contents of the folder and thus supersedes any previous index. An Index Update amends an existing index with new information, not affecting any entries not included in the message.

So that wipes out any information previously sent. If you want to continue where you were (which you likely do since you send the required info in the cluster-config), you need to send index updates.

5

What exactly wipes out the information? The Index is send only once (+ IndexUpdates later) before disconnect. After reconnect, It just sends ClusterConfig (with proper index_id & sequences).

I expect, that after reconnect, only ClusterConfigs are exchanged, and as all files are sync, nothing should be done, except pings.

6

2023-03-12_20-51

Interesting note, that after disconnection, it displays up to date state (as expected).

7

It’s not once only according to logs. First block:

[4QDTF] 2023/03/12 19:27:42.694841 model.go:1129: DEBUG: Index (in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH / "lwmfe-w394s": 0 files

Second block after reconnect and cluster config:

[4QDTF] 2023/03/12 19:28:29.352342 model.go:1129: DEBUG: Index (in): WICHSMT-QDEQWEA-7ZPOJLT-HHBYCTL-4Q4NWOJ-PSDC7FW-DW7IYEZ-HSBJDQH / "lwmfe-w394s": 0 files

Not that updates are ... DEBUG: Index update (in): ...

1 Like
8

Oh, yeah, indeed, thank you, I didn’t noticed that index is send twice, and even if it has the same sequence and no files, the files sent in previous session are forgotten.

Thanks you)

1 Like