"different encryption passwords used" when adding a receive encrypted folder

tomasz86 · August 27, 2021, 3:05am

I have experienced this problem today.

On D4DZUG, I shared an existing folder, password protected, with TLFGVK.
On TLFGVK, I added the folder as Receive Encrypted.
The connection between D4DZUG and TLFGVK was dropped with errors about “different encryption passwords used”.

These are logs from the two with db and model enabled. I tried to pause everything unrelated first before enabling debug logging, so that only the two devices and the folder in question was operating.

Is there anything useful in the logs?

D4DZU:

11:41:32.349233 api.go:741: INFO: Enabled debug data for "xxx"
11:41:33.350655 api.go:741: INFO: Enabled debug data for "xxx"
11:41:38.071959 service.go:343: INFO: Established secure connection to TLFGVKC at 10.0.0.2:51656-172.105.199.155:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
11:41:38.074960 indexhandler.go:545: DEBUG: Not resuming index handler for device TLFGVKC and folder jvtg5-hymk6 as none is paused and there is no start info
11:41:38.074960 model.go:2217: INFO: Device TLFGVKC client is "xxx" named "xxx" at 10.0.0.2:51656-172.105.199.155:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
11:41:38.074960 set.go:371: DEBUG: jvtg5-hymk6 IndexID(7777777)
11:41:38.075960 set.go:371: DEBUG: jvtg5-hymk6 IndexID(HTNCZ5L)
11:41:38.075960 set.go:371: DEBUG: jvtg5-hymk6 IndexID(MM7CYGA)
11:41:38.156978 set.go:371: DEBUG: jvtg5-hymk6 IndexID(TLFGVKC)
11:41:38.157078 set.go:371: DEBUG: jvtg5-hymk6 IndexID(VAVIRLX)
11:41:38.157078 set.go:371: DEBUG: jvtg5-hymk6 IndexID(XZZTDIY)
11:41:38.157078 set.go:371: DEBUG: jvtg5-hymk6 IndexID(6I7GNCY)
11:41:38.157078 set.go:371: DEBUG: jvtg5-hymk6 IndexID(6S74ITS)
11:41:38.699602 service.go:296: INFO: Connected to already connected device TLFGVKC (existing: 10.0.0.2:51656-172.105.199.155:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 new: 10.0.0.2:51668-139.162.117.43:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256)
11:41:39.872202 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:41:39.872714 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
11:41:39.873237 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:41:39.875858 model.go:894: DEBUG: model@0xc000eab040 Completion(TLFGVKC, "xxx"): map[completion:0 globalBytes:274998620 globalItems:9950 needBytes:274998620 needDeletes:0 needItems:9950 sequence:0]
11:41:39.876401 progressemitter.go:290: DEBUG: progress emitter: bytes completed for yjjea-2q5p5: 0
11:41:39.877154 folder_summary.go:354: DEBUG: Error getting completion for folder yjjea-2q5p5, device TLFGVKC: folder is paused
11:41:39.877154 progressemitter.go:290: DEBUG: progress emitter: bytes completed for capi4-h3srq: 0
11:41:39.878829 folder_summary.go:354: DEBUG: Error getting completion for folder capi4-h3srq, device TLFGVKC: folder is paused
11:41:39.878829 progressemitter.go:290: DEBUG: progress emitter: bytes completed for kkuhc-b34ee: 0
11:41:39.880509 folder_summary.go:354: DEBUG: Error getting completion for folder kkuhc-b34ee, device TLFGVKC: folder is paused
11:41:39.880509 progressemitter.go:290: DEBUG: progress emitter: bytes completed for c5vov-haafs: 0
11:41:39.881572 folder_summary.go:354: DEBUG: Error getting completion for folder c5vov-haafs, device TLFGVKC: folder is paused
11:41:39.881572 progressemitter.go:290: DEBUG: progress emitter: bytes completed for q5euc-d6f2d: 0
11:41:39.882091 folder_summary.go:354: DEBUG: Error getting completion for folder q5euc-d6f2d, device TLFGVKC: folder is paused
11:41:39.882091 progressemitter.go:290: DEBUG: progress emitter: bytes completed for gjhfl-4nzzc: 0
11:41:39.882609 folder_summary.go:354: DEBUG: Error getting completion for folder gjhfl-4nzzc, device TLFGVKC: folder is paused
11:41:39.882609 progressemitter.go:290: DEBUG: progress emitter: bytes completed for gjfnh-vvfnn: 0
11:41:39.883133 folder_summary.go:354: DEBUG: Error getting completion for folder gjfnh-vvfnn, device TLFGVKC: folder is paused
11:41:39.883133 progressemitter.go:290: DEBUG: progress emitter: bytes completed for kazza-hew2c: 0
11:41:39.884156 folder_summary.go:354: DEBUG: Error getting completion for folder kazza-hew2c, device TLFGVKC: folder is paused
11:41:39.884219 progressemitter.go:290: DEBUG: progress emitter: bytes completed for w9h6p-vpccd: 0
11:41:39.884937 folder_summary.go:354: DEBUG: Error getting completion for folder w9h6p-vpccd, device TLFGVKC: folder is paused
11:41:39.884937 progressemitter.go:290: DEBUG: progress emitter: bytes completed for m65ep-rgntd: 0
11:41:39.885537 folder_summary.go:354: DEBUG: Error getting completion for folder m65ep-rgntd, device TLFGVKC: folder is paused
11:41:39.885537 progressemitter.go:290: DEBUG: progress emitter: bytes completed for fxvvx-etjrn: 0
11:41:39.886580 folder_summary.go:354: DEBUG: Error getting completion for folder fxvvx-etjrn, device TLFGVKC: folder is paused
11:41:39.886580 progressemitter.go:290: DEBUG: progress emitter: bytes completed for ctz3i-ewkem: 0
11:41:39.887096 folder_summary.go:354: DEBUG: Error getting completion for folder ctz3i-ewkem, device TLFGVKC: folder is paused
11:41:39.887096 progressemitter.go:290: DEBUG: progress emitter: bytes completed for nduzw-sud32: 0
11:41:39.887615 folder_summary.go:354: DEBUG: Error getting completion for folder nduzw-sud32, device TLFGVKC: folder is paused
11:41:39.887615 progressemitter.go:290: DEBUG: progress emitter: bytes completed for xmptn-sxvx5: 0
11:41:39.888135 folder_summary.go:354: DEBUG: Error getting completion for folder xmptn-sxvx5, device TLFGVKC: folder is paused
11:41:39.888658 progressemitter.go:290: DEBUG: progress emitter: bytes completed for quzsh-twmdg: 0
11:41:39.889174 folder_summary.go:354: DEBUG: Error getting completion for folder quzsh-twmdg, device TLFGVKC: folder is paused
11:41:39.889174 progressemitter.go:290: DEBUG: progress emitter: bytes completed for orxwk-ztxia: 0
11:41:39.889704 folder_summary.go:354: DEBUG: Error getting completion for folder orxwk-ztxia, device TLFGVKC: folder is paused
11:41:39.889704 progressemitter.go:290: DEBUG: progress emitter: bytes completed for 9pzqk-mllzf: 0
11:41:39.890743 folder_summary.go:354: DEBUG: Error getting completion for folder 9pzqk-mllzf, device TLFGVKC: folder is paused
11:41:39.890743 progressemitter.go:290: DEBUG: progress emitter: bytes completed for qojqz-thphx: 0
11:41:39.891262 folder_summary.go:354: DEBUG: Error getting completion for folder qojqz-thphx, device TLFGVKC: folder is paused
11:41:39.891262 progressemitter.go:290: DEBUG: progress emitter: bytes completed for scgkp-whuux: 0
11:41:39.891782 folder_summary.go:354: DEBUG: Error getting completion for folder scgkp-whuux, device TLFGVKC: folder is paused
11:41:39.935605 model.go:1133: DEBUG: Handling ClusterConfig from TLFGVKC
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder 9pzqk-mllzf
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder 9pzqk-mllzf
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder c5vov-haafs
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder c5vov-haafs
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder capi4-h3srq
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder capi4-h3srq
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder ctz3i-ewkem
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder ctz3i-ewkem
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder fxvvx-etjrn
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder fxvvx-etjrn
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjfnh-vvfnn
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjfnh-vvfnn
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjhfl-4nzzc
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjhfl-4nzzc
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder kazza-hew2c
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder kazza-hew2c
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder kkuhc-b34ee
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder kkuhc-b34ee
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder m65ep-rgntd
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder m65ep-rgntd
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder nduzw-sud32
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder nduzw-sud32
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder orxwk-ztxia
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder orxwk-ztxia
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder q5euc-d6f2d
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder q5euc-d6f2d
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder qojqz-thphx
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder qojqz-thphx
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder quzsh-twmdg
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder quzsh-twmdg
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder scgkp-whuux
11:41:39.935605 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder scgkp-whuux
11:41:39.935605 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder w9h6p-vpccd
11:41:39.936117 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder w9h6p-vpccd
11:41:39.936117 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder xmptn-sxvx5
11:41:39.936117 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder xmptn-sxvx5
11:41:39.936117 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder yjjea-2q5p5
11:41:39.936117 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder yjjea-2q5p5
11:41:51.268981 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:42:09.009610 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:42:26.826283 model.go:1133: DEBUG: Handling ClusterConfig from TLFGVKC
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder 9pzqk-mllzf
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder 9pzqk-mllzf
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder c5vov-haafs
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder c5vov-haafs
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder capi4-h3srq
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder capi4-h3srq
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder ctz3i-ewkem
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder ctz3i-ewkem
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder fxvvx-etjrn
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder fxvvx-etjrn
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjfnh-vvfnn
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjfnh-vvfnn
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjhfl-4nzzc
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjhfl-4nzzc
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder jvtg5-hymk6
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder jvtg5-hymk6
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder kazza-hew2c
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder kazza-hew2c
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder kkuhc-b34ee
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder kkuhc-b34ee
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder m65ep-rgntd
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder m65ep-rgntd
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder nduzw-sud32
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder nduzw-sud32
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder orxwk-ztxia
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder orxwk-ztxia
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder q5euc-d6f2d
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder q5euc-d6f2d
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder qojqz-thphx
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder qojqz-thphx
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder quzsh-twmdg
11:42:26.827214 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder quzsh-twmdg
11:42:26.827214 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder scgkp-whuux
11:42:26.828249 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder scgkp-whuux
11:42:26.828249 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder w9h6p-vpccd
11:42:26.828249 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder w9h6p-vpccd
11:42:26.828249 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder xmptn-sxvx5
11:42:26.828249 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder xmptn-sxvx5
11:42:26.828249 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder yjjea-2q5p5
11:42:26.828249 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder yjjea-2q5p5
11:42:31.726334 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:42:32.559018 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:42:36.446149 model.go:1133: DEBUG: Handling ClusterConfig from TLFGVKC
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder 9pzqk-mllzf
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder 9pzqk-mllzf
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder c5vov-haafs
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder c5vov-haafs
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder capi4-h3srq
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder capi4-h3srq
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder ctz3i-ewkem
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder ctz3i-ewkem
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder fxvvx-etjrn
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder fxvvx-etjrn
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjfnh-vvfnn
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjfnh-vvfnn
11:42:36.446149 indexhandler.go:459: DEBUG: Removing index handler for device TLFGVKC and folder gjhfl-4nzzc
11:42:36.446149 indexhandler.go:465: DEBUG: Removed index handler for device TLFGVKC and folder gjhfl-4nzzc
11:42:36.519507 model.go:1327: WARNING: Failure checking encryption consistency with device TLFGVKC for folder "xxx" (jvtg5-hymk6): different encryption passwords used
11:42:36.521053 model.go:1714: INFO: Connection to TLFGVKC at 10.0.0.2:51656-172.105.199.155:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: handling cluster-config: different encryption passwords used
11:42:47.785295 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.785295 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
11:42:47.786369 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.786369 model.go:894: DEBUG: model@0xc000eab040 Completion(7777777, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:49940]
11:42:47.787442 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.787442 model.go:894: DEBUG: model@0xc000eab040 Completion(HTNCZ5L, "xxx"): map[completion:98.78393135209188 globalBytes:274998620 globalItems:9950 needBytes:3344172 needDeletes:20 needItems:71 sequence:19957]
11:42:47.788547 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.788547 model.go:894: DEBUG: model@0xc000eab040 Completion(MM7CYGA, "xxx"): map[completion:98.78393135209188 globalBytes:274998620 globalItems:9950 needBytes:3344172 needDeletes:20 needItems:71 sequence:19858]
11:42:47.789605 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.789605 model.go:894: DEBUG: model@0xc000eab040 Completion(TLFGVKC, "xxx"): map[completion:0 globalBytes:274998620 globalItems:9950 needBytes:274998620 needDeletes:0 needItems:9950 sequence:0]
11:42:47.791168 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.791168 model.go:894: DEBUG: model@0xc000eab040 Completion(VAVIRLX, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:59691]
11:42:47.791692 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.792222 model.go:894: DEBUG: model@0xc000eab040 Completion(XZZTDIY, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:59745]
11:42:47.793273 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.793273 model.go:894: DEBUG: model@0xc000eab040 Completion(6I7GNCY, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:10058]
11:42:47.794327 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:47.794327 model.go:894: DEBUG: model@0xc000eab040 Completion(6S74ITS, "xxx"): map[completion:99.96646964992041 globalBytes:274998620 globalItems:9950 needBytes:92208 needDeletes:20 needItems:49 sequence:9979]
11:42:47.881882 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:42:52.500277 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:43:12.522174 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:43:33.107047 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:43:53.085857 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:43:55.419234 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.419234 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
11:43:55.419757 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.420272 model.go:894: DEBUG: model@0xc000eab040 Completion(7777777, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:49940]
11:43:55.420799 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.420799 model.go:894: DEBUG: model@0xc000eab040 Completion(HTNCZ5L, "xxx"): map[completion:98.78393135209188 globalBytes:274998620 globalItems:9950 needBytes:3344172 needDeletes:20 needItems:71 sequence:19957]
11:43:55.421840 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.421840 model.go:894: DEBUG: model@0xc000eab040 Completion(MM7CYGA, "xxx"): map[completion:98.78393135209188 globalBytes:274998620 globalItems:9950 needBytes:3344172 needDeletes:20 needItems:71 sequence:19858]
11:43:55.422860 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.422884 model.go:894: DEBUG: model@0xc000eab040 Completion(TLFGVKC, "xxx"): map[completion:0 globalBytes:274998620 globalItems:9950 needBytes:274998620 needDeletes:0 needItems:9950 sequence:0]
11:43:55.423405 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.423908 model.go:894: DEBUG: model@0xc000eab040 Completion(VAVIRLX, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:59691]
11:43:55.424438 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.424438 model.go:894: DEBUG: model@0xc000eab040 Completion(XZZTDIY, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:59745]
11:43:55.425481 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.425481 model.go:894: DEBUG: model@0xc000eab040 Completion(6I7GNCY, "xxx"): map[completion:100 globalBytes:274998620 globalItems:9950 needBytes:0 needDeletes:0 needItems:0 sequence:10058]
11:43:55.426526 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:43:55.426526 model.go:894: DEBUG: model@0xc000eab040 Completion(6S74ITS, "xxx"): map[completion:99.96646964992041 globalBytes:274998620 globalItems:9950 needBytes:92208 needDeletes:20 needItems:49 sequence:9979]
11:43:55.952500 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:44:13.237614 folder.go:208: DEBUG: sendreceive/jvtg5-hymk6@0xc0005f0380 Scan due to watcher
11:44:13.238129 folder.go:414: DEBUG: sendreceive/jvtg5-hymk6@0xc0005f0380 scanning
11:44:13.240184 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:44:13.240184 set.go:254: DEBUG: jvtg5-hymk6 Get(Joplin)
11:44:13.240698 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:44:13.246941 set.go:254: DEBUG: jvtg5-hymk6 Get(Joplin\locks)
11:44:13.247454 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
11:44:13.247454 set.go:220: DEBUG: jvtg5-hymk6 WithPrefixedHaveTruncated(7777777, "xxx")
11:44:13.247975 folder.go:482: DEBUG: sendreceive/jvtg5-hymk6@0xc0005f0380 finished scanning, detected 0 changes
11:44:13.715300 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:44:33.635256 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:44:34.283334 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:44:54.392843 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:45:14.508991 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:45:33.661784 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:45:39.312369 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:45:50.909804 service.go:277: INFO: Connection from QBYTKED at 172.105.199.155:22067 (relay-server) rejected: device is ignored
11:45:59.308222 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:46:20.022614 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:46:33.651149 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (tcp-server) rejected: device is paused
11:46:40.060428 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused
11:47:02.237126 service.go:277: INFO: Connection from XZZTDIY at 10.0.0.3:22000 (quic-server) rejected: device is paused

TLFGVK:

04:41:44.627989 api.go:741: INFO: Enabled debug data for "xxx"
04:41:45.546780 api.go:741: INFO: Enabled debug data for "xxx"
04:42:23.169595 model.go:2767: INFO: Paused folder "xxx" (jvtg5-hymk6)
04:42:23.177601 model.go:2949: DEBUG: Discarding now shared pending folder jvtg5-hymk6 for device D4DZUGP
04:42:26.858416 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (tcp-server) rejected: device is paused
04:42:27.160739 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (tcp-server) rejected: device is paused
04:42:33.411136 lowlevel.go:970: INFO: No stored folder metadata for "xxx"; recalculating
04:42:33.459784 lowlevel.go:516: DEBUG: global db check completed for [106 118 116 103 53 45 104 121 109 107 54]
04:42:33.484879 set.go:371: DEBUG: jvtg5-hymk6 IndexID(7777777)
04:42:33.487879 set.go:394: DEBUG: jvtg5-hymk6 MtimeFS()
04:42:33.492882 model.go:419: INFO: Ready to synchronize "xxx" (jvtg5-hymk6) (receiveencrypted)
04:42:33.492882 set.go:371: DEBUG: jvtg5-hymk6 IndexID(7777777)
04:42:33.492882 indexhandler.go:73: DEBUG: Device D4DZUGP folder "xxx" (jvtg5-hymk6) has no index ID for us
04:42:33.492882 set.go:371: DEBUG: jvtg5-hymk6 IndexID(D4DZUGP)
04:42:33.492882 indexhandler.go:95: INFO: Device D4DZUGP folder "xxx" (jvtg5-hymk6) has a new index ID (0x7AB10A28B2B4A894)
04:42:33.492882 set.go:70: DEBUG: jvtg5-hymk6 Drop(D4DZUGP)
04:42:33.494884 set.go:386: DEBUG: jvtg5-hymk6 SetIndexID(D4DZUGP, 0x7AB10A28B2B4A894)
04:42:33.495885 indexhandler.go:540: DEBUG: Started index handler for device D4DZUGP and folder jvtg5-hymk6 in resume
04:42:33.495885 model.go:541: INFO: Unpaused folder "xxx" (jvtg5-hymk6) (receiveencrypted)
04:42:33.495885 set.go:371: DEBUG: jvtg5-hymk6 IndexID(D4DZUGP)
04:42:33.495885 set.go:371: DEBUG: jvtg5-hymk6 IndexID(7777777)
04:42:33.497886 folder.go:144: DEBUG: receiveencrypted/jvtg5-hymk6@0xc000b5e380 starting
04:42:33.497886 folder.go:195: DEBUG: receiveencrypted/jvtg5-hymk6@0xc000b5e380 Scanning due to timer
04:42:33.497886 folder.go:414: DEBUG: receiveencrypted/jvtg5-hymk6@0xc000b5e380 scanning
04:42:33.498886 indexhandler.go:132: DEBUG: Starting index handler for jvtg5-hymk6 to D4DZUGP at 20.0.0.2:5567-172.105.199.155:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 (slv=0)
04:42:33.498886 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.498886 set.go:210: DEBUG: jvtg5-hymk6 WithHaveSequence(1)
04:42:33.558916 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.558916 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.558916 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.558916 set.go:220: DEBUG: jvtg5-hymk6 WithPrefixedHaveTruncated(7777777, "xxx")
04:42:33.632474 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.632474 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
04:42:33.637477 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.642480 model.go:894: DEBUG: model@0xc0004101a0 Completion(D4DZUGP, "xxx"): map[completion:100 globalBytes:0 globalItems:0 needBytes:0 needDeletes:0 needItems:0 sequence:0]
04:42:33.729050 folder.go:482: DEBUG: receiveencrypted/jvtg5-hymk6@0xc000b5e380 finished scanning, detected 0 changes
04:42:33.729050 folder.go:862: INFO: Completed initial scan of receiveencrypted folder "xxx" (jvtg5-hymk6)
04:42:33.737556 folder.go:291: DEBUG: receiveencrypted/jvtg5-hymk6@0xc000b5e380 next rescan in 26h54m22.709140805s
04:42:33.737556 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:33.737556 set.go:178: DEBUG: jvtg5-hymk6 WithNeed(7777777)
04:42:34.022505 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:34.022505 model.go:894: DEBUG: model@0xc0004101a0 Completion(D4DZUGP, "xxx"): map[completion:100 globalBytes:0 globalItems:0 needBytes:0 needDeletes:0 needItems:0 sequence:0]
04:42:34.966445 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:34.966445 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
04:42:37.239643 model.go:1714: INFO: Connection to D4DZUGP at 20.0.0.2:5567-172.105.199.155:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: closed by remote: handling cluster-config: different encryption passwords used
04:42:37.249639 indexhandler.go:137: DEBUG: Exiting index handler for jvtg5-hymk6 to D4DZUGP at 20.0.0.2:5567-172.105.199.155:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: context canceled
04:42:38.979474 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:38.979474 progressemitter.go:290: DEBUG: progress emitter: bytes completed for jvtg5-hymk6: 0
04:42:38.981977 set.go:156: DEBUG: jvtg5-hymk6 Snapshot()
04:42:38.981977 model.go:894: DEBUG: model@0xc0004101a0 Completion(D4DZUGP, "xxx"): map[completion:100 globalBytes:0 globalItems:0 needBytes:0 needDeletes:0 needItems:0 sequence:0]
04:42:47.217924 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:43:07.221312 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:43:27.248354 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (tcp-server) rejected: device is paused
04:43:27.672736 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:43:47.605290 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:44:07.651964 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:44:27.271639 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (tcp-server) rejected: device is paused
04:44:27.603054 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:44:47.888667 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:45:14.019311 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:45:27.227599 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (tcp-server) rejected: device is paused
04:45:33.677559 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused
04:45:52.494676 service.go:277: INFO: Connection from CWXZ7CV at 20.0.0.3:22000 (quic-server) rejected: device is paused

calmh · August 27, 2021, 11:11am

In principle this should mean that the folder was shared with this device previously with a different password, and it has data from that time? (That data is invalid if the password was changed.)

tomasz86 · August 27, 2021, 1:03pm

It was shared with the same device previously, but also as Receive Encrypted. There has never been any password set on the receiving side. Last time, the folder was removed from the device later, both using the Syncthing GUI, and also physically from the disk. At the moment, there is no previous data on the receiving side at all.

calmh · August 27, 2021, 2:51pm

If it was shared previously, there’s some index metadata at least. Remove the folder on the receiving side. Re-add it when prompted. Should resolve.

imsodin · August 28, 2021, 8:56am

There’s an encryption token (syncthing-encryption_password_token) inside the folder marker (.stfolder), and that token is used to check against password consistency. That should be removed, respectively .stfolder should be renamed when you remove the folder. Maybe that didn’t happen and you still have the old token?

tomasz86 · August 28, 2021, 9:13am

I did remove it completely before trying to add it again though, but there was no difference. I’m going to do more testing later on when possible, as this is a remote device that I only have somewhat limited access to.

I’ve tried to reproduce the issue in my test environment, but here everything works as expected.

Yeah, the whole folder, together with .stfolder in it, had been physically deleted from the disk before trying to add it again, so this shouldn’t be an issue, I think. As said above, I’m going to give this one more try shortly and will report the results.

tomasz86 · August 29, 2021, 4:29am

I’ve just done another round of testing. Unfortunately, there is no difference. I start completely from scratch regarding the folder. First, on D4DZUG I share it with TLFGVK and set a new encryption password. Then, on TLFGVK I accept the folder as receive encrypted using a new, non-existing path. Immediately, I get the error message about a “different encryption password” and the connection drops.

Since the problem is 100% reproducible on my end, is there anything else that I can do regarding debugging, so that we could find the culprit here?

tomasz86 · August 30, 2021, 6:17am

I can also add that when adding the folder on TLFGVK, it always starts up paused for some reason (even though folder defaults are set to “unpaused”). As soon as I unpause it, I get the errors explained in details above.

imsodin · August 30, 2021, 6:45am

Can you please provide logs with model debug enabled of the process starting with adding the new folder on the trusted device until the password error occurs.

tomasz86 · August 31, 2021, 4:37am

I’ve done the following.

Pause all folders on TLFGVK, and all folders on D4DZUG except the one that I was going to share as encrypted.
Pause all other devices on both D4DZUG and TLFGVK.
Shut Syncthing down on both D4DZUG and TLFGVK.
Delete all previous logfiles on both sides.
Start Syncthing again on both devices with model enabled.
Wait for the two to connect with each other.
Share the folder from D4DZUG to TLFGVK with a new, random encryption password.
Accept the folder on TLFGVK using a new, empty path.
Connection between D4DZUG and TLFGVK dropped.
Connection resumed and the folder began syncing properly!

It seems that the original problem is gone, so I can only say sorry for the previous postings. The only difference that I can think of is that this time I restarted Syncthing on both devices before doing the testing, while previously everything was likely done without any restarts. The folder on both sides is currently marked as “Up to Date” and appears fully in sync.

However, there is a different issue that I have also observed previously, which is that on each connection drop and reconnection between the two devices, the index of the Receive Encrypted folder seems to be send again and again from D4DZUG to TLFGVK, which takes a while due to the slow connection and thousands of files. Is this normal? I’m going to do more testing regarding this in my test environment to see if the behaviour persist there.

imsodin · September 2, 2021, 8:43pm

We don’t clean up the password tokens, that may be related to seeing problems when not restarting: https://github.com/syncthing/syncthing/pull/7925

tomasz86 · September 8, 2021, 1:57am

That was likely the culprit. I’ve tried to reproduce the issue with the current main, but to no avail.

Thanks for the quick fix !

system · October 8, 2021, 1:57am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.