Connection repeatedly closed and "deleted file with non-empty block list" in logs

I’ve run syncthing for about 2 years with minimal problems. I noticed some issues recently I haven’t been able to solve on my own. I searched for the errors I could and similar problems on this forum, but wasn’t able to solve it.

Posting all the relevant info I can think of as well as a log. I may sound like I know what I’m doing, but I’m a self-taught “occasional evenings and weekends” type so more explanation is better. Thanks in advance.

Issues:

  • File transfer rates are lower than what I saw previously or drop to zero.
  • Machines connect intermittently; connected, then closed every minute or so.
  • looking at the logs I see the connection made to my Linux/ARM server then
    • "Connection to M6MUPEE-[...] closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list" (I searched for this file on the iMac (YZK4P) and Banana Pi (M6MUPEE) and couldn’t find it.
    • or
    • Connection to M6MUPEE[...] closed: reading length: EOF

Set up:

Latest syncthing on 2 macs and one BananaPi (ARM) - (there are colleagues computers connected, but I don’t seem to be having an issue with those). v0.14.33, Linux (ARM) v0.14.33-dirty, Mac OS X

The computers are all on one local network. The router is running Shibby’s Tomato firmware with UPNP and NAT-PMP on LAN enabled. I suspected the router after reading some posts here, so reinstalled the factory firmware, but it didn’t help so I switched back.

Sample log:

Not sure what’s important to redact here (if anything) but I took out parts of the Device ID and external IP addresses and replaced with […]. Please let me know if I should post more specific info, or edit something out! Thanks

    [YZK4P] 11:09:34 INFO: syncthing v0.14.33-dirty "Dysprosium Dragonfly" (go1.8.3 darwin-amd64) brew@ElCapitan-2.local 2017-07-13 06:55:12 UTC [noupgrade]
[YZK4P] 11:09:34 INFO: My ID: YZK4PNX-4NX4D2B-[...]KHWJJQQ
[YZK4P] 11:09:35 INFO: Single thread SHA256 performance is 222 MB/s using minio/sha256-simd (159 MB/s using crypto/sha256).
[YZK4P] 11:09:36 INFO: Hashing performance with weak hash is 177.98 MB/s
[YZK4P] 11:09:36 INFO: Hashing performance without weak hash is 209.83 MB/s
[YZK4P] 11:09:36 INFO: Weak hash enabled, as it has an acceptable performance impact.
[YZK4P] 11:09:37 INFO: Starting deadlock detector with 20m0s timeout
[YZK4P] 11:09:37 INFO: Ready to synchronize torrent-watch (readwrite)
[YZK4P] 11:09:38 INFO: Ready to synchronize "C4AA-Shared" (5fwh2-ka4dj) (readwrite)
[YZK4P] 11:09:38 INFO: Ready to synchronize "Imac stuff" (vfmvt-mjy5z) (readwrite)
[YZK4P] 11:09:38 INFO: Ready to synchronize Mine (readwrite)
[YZK4P] 11:09:40 INFO: Ready to synchronize Pending (readwrite)
[YZK4P] 11:09:40 INFO: Ready to synchronize "Pi to All" (kn3jp-iqzwq) (readwrite)
[YZK4P] 11:09:40 INFO: Ready to synchronize "steve-to-victoria" (zgiem-jsfqu) (readwrite)
[YZK4P] 11:09:40 INFO: Send rate is unlimited, receive rate is unlimited
[YZK4P] 11:09:40 INFO: Rate limits do not apply to LAN connections
[YZK4P] 11:09:40 INFO: Using discovery server https://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[YZK4P] 11:09:40 INFO: Using discovery server https://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[YZK4P] 11:09:40 INFO: TCP listener ([::]:22000) starting
[YZK4P] 11:09:40 INFO: Using discovery server https://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[YZK4P] 11:09:40 INFO: Completed initial scan (rw) of "Imac stuff" (vfmvt-mjy5z)
[YZK4P] 11:09:40 INFO: Completed initial scan (rw) of "steve-to-victoria" (zgiem-jsfqu)
[YZK4P] 11:09:40 INFO: Completed initial scan (rw) of "Pi to All" (kn3jp-iqzwq)
[YZK4P] 11:09:41 INFO: Completed initial scan (rw) of torrent-watch
[YZK4P] 11:09:41 INFO: Completed initial scan (rw) of Pending
[YZK4P] 11:09:42 INFO: Using discovery server https://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC
[YZK4P] 11:09:43 INFO: Completed initial scan (rw) of Mine
[YZK4P] 11:09:44 INFO: Using discovery server https://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ
[YZK4P] 11:09:44 INFO: Using discovery server https://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[YZK4P] 11:09:45 INFO: GUI and API listening on 127.0.0.1:8384
[YZK4P] 11:09:45 INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
[YZK4P] 11:09:45 INFO: Device BLZPL4Y-YWFBIAU-[...]SKK66AV is "Rebecca Bray" at [dynamic]
[YZK4P] 11:09:45 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 is "bananapi-armbian" at [dynamic]
[YZK4P] 11:09:45 INFO: Device OQHJB2N-UW5TJLL-[...]2VYXXAN is "steve-iphone-6+" at [dynamic]
[YZK4P] 11:09:45 INFO: Device RB6ASO2-DUXXMHI-[...]RJE7YAH is "Victoria Macbook Air" at [dynamic]
[YZK4P] 11:09:45 INFO: Device YZK4PNX-4NX4D2B-[...]KHWJJQQ is "steve-imac" at [dynamic]
[YZK4P] 11:09:45 INFO: Device Z33UZEF-OH7L[...]XAG36AI is "steve-mbp" at [dynamic]
[YZK4P] 11:09:45 INFO: Starting usage reporting
[YZK4P] 11:09:45 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:56593-192.99.59.139:443 (relay-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:09:45 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:09:47 INFO: Completed initial scan (rw) of "C4AA-Shared" (5fwh2-ka4dj)
[YZK4P] 11:09:51 INFO: New NAT port mapping: external TCP address 69.118.84.131:60216 to local address 0.0.0.0:22000.
[YZK4P] 11:09:51 INFO: New NAT port mapping: external TCP address 69.118.84.131:25476 to local address 0.0.0.0:22000.
[YZK4P] 11:09:51 INFO: Detected 2 NAT devices
[YZK4P] 11:09:53 INFO: Joined relay relay://108.28.183.249:22067
[YZK4P] 11:10:00 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:10:00 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:56704-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:10:00 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:10:16 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:10:22 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:56731-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:10:22 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:10:22 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:10:40 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:56748-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:10:40 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:13:10 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: read timeout
[YZK4P] 11:13:42 INFO: Failed to exchange Hello messages with M6MUPEE-EP3XNYQ-[...]S2O3EA3 ([fe80::d1:7ff:fe40:8b37%en1]:22000): read tcp [fe80::7e6d:62ff:fe73:e56a%en1]:56886->[fe80::d1:7ff:fe40:8b37%en1]:22000: i/o timeout
[YZK4P] 11:18:27 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57119-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:18:27 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:18:41 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:19:25 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57168-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:19:25 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:19:25 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:19:50 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:22000-[fe80::d1:7ff:fe40:8b37%en1]:42524 (tcp-server) (TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:19:50 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:20:06 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:20:39 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57222-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:20:39 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:20:39 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:21:02 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:22000-[fe80::d1:7ff:fe40:8b37%en1]:42584 (tcp-server) (TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:21:02 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:21:15 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:21:23 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:57286-192.168.1.60:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:21:23 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:21:23 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:21:38 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57324-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:21:38 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:21:53 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:22:36 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:57370-192.168.1.60:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:22:36 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:22:36 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:22:38 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57388-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:22:38 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:22:53 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:23:48 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57440-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:23:48 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:23:48 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:23:59 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:57465-192.168.1.60:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:23:59 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:24:15 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:24:46 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57501-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:24:46 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:24:46 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:25:08 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:57525-192.168.1.60:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:25:08 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:25:23 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: protocol error: index: ".sync-conflict-20160524-111626.DS_Store": deleted file with non-empty block list
[YZK4P] 11:25:46 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at [fe80::7e6d:62ff:fe73:e56a%en1]:57556-[fe80::d1:7ff:fe40:8b37%en1]:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:25:46 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"
[YZK4P] 11:25:46 INFO: Connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 closed: reading length: EOF
[YZK4P] 11:26:23 INFO: Established secure connection to M6MUPEE-EP3XNYQ-[...]S2O3EA3 at 192.168.1.29:57583-192.168.1.60:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[YZK4P] 11:26:23 INFO: Device M6MUPEE-EP3XNYQ-[...]S2O3EA3 client is "syncthing v0.14.33" named "bananapi-armbian"

So iphone6+ device implies you are using a custom client. It seems that the custom client is not respecting the protocol specification and sending files as deleted yet specify there is content in them.

That’s the first problem you should solve, we can dive deeper if the issue persists once this is fixed.

The error isn’t with that device though. Even if it might have been the cause, this is probably an index entry that “escaped” into the other devices before we added that check. The solution is to wipe the index, as this is a corrupt and disallowed index entry.

syncthing -reset-database on the M6MUPEE device to begin with. Repeat as necessary.

Thanks for the response. I’m using fsync() on an iPhone - rarely, it’s basically for “emergencies” where I might have my phone and not a laptop and need some document. Would you recommend not using it, based on this?

Thank you so much. Will get started down this path and report back.

I am not recommending not using it, as that’s the only option there is, but perhaps we should engage more with the developer to patch up the holes.

This solved the problem. Thanks so much.

I appreciate the speedy response and it made me realize how much I value this software. I made a little donation as a gesture of my gratitude for everyone’s work. Thanks again!

Oh - and way back when I posted this little tutorial on installing syncthing on OS X/macOS for newcomers. I wrote it for a friend then just made it public.

2 Likes

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