How to debug TLS Handshake error?

Nutomic · February 5, 2018, 6:14pm

I’m currently trying to debug a problem in Syncthing Lite regarding TLS handshakes. Hello messages are transmitted fine, but after that, the Syncthing side shows this error:

[VQ65P] 2018/02/06 03:06:31.020820 tcp_listen.go:103: DEBUG: Listen (BEP/tcp): connect from 172.30.1.26:46478
[VQ65P] 2018/02/06 03:06:31.022197 tcp_listen.go:117: INFO: Listen (BEP/tcp): TLS handshake: EOF

However, the Android site shows a successful TLS handshake, with the ciphersuite TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256. The Syncthing web gui also shows the Android device as connected. But reading from the socket afterwards causes an EOFException.

Originally I thought this was caused because ALPN isn’t working on the Android side, but looking at the Syncthing code, this doesn’t seem to be required.

Can you tell me how I can get more error information out of Syncthing, or other ways to debug and fix this? Source code for connecting and TLS is in these files:

github.com

Nutomic/syncthing-java/blob/master/bep/src/main/kotlin/net/syncthing/java/bep/ConnectionHandler.kt

/* 
 * Copyright (C) 2016 Davide Imbriaco
 *
 * This Java file is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/.
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package net.syncthing.java.bep

import com.google.protobuf.ByteString
import com.google.protobuf.MessageLite
import net.jpountz.lz4.LZ4Factory
import net.syncthing.java.bep.BlockExchangeProtos.*
import net.syncthing.java.client.protocol.rp.RelayClient

This file has been truncated. show original

github.com

Nutomic/syncthing-java/blob/master/core/src/main/kotlin/net/syncthing/java/core/security/KeystoreHandler.kt

/* 
 * Copyright (C) 2016 Davide Imbriaco
 *
 * This Java file is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/.
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package net.syncthing.java.core.security

import net.syncthing.java.core.beans.DeviceId
import net.syncthing.java.core.configuration.Configuration
import net.syncthing.java.core.interfaces.RelayConnection
import net.syncthing.java.core.utils.NetworkUtils
import org.apache.commons.codec.binary.Base32

This file has been truncated. show original

github.com

Nutomic/syncthing-java/blob/master/core/src/main/kotlin/net/syncthing/java/core/security/TlsSocketFactory.kt

package net.syncthing.java.core.security

import java.io.IOException
import java.io.InputStream
import java.net.InetAddress
import java.net.Socket
import java.net.UnknownHostException
import java.security.*
import java.security.cert.CertificateException
import java.security.cert.X509Certificate
import javax.net.ssl.*

/**
 * Pre-Lollipop Android devices do not support TLS 1.1 and 1.2 by default, so we have to enable them manually.
 *
 * https://stackoverflow.com/a/38863705
 * http://blog.dev-area.net/2015/08/13/android-4-1-enable-tls-1-1-and-tls-1-2/
 */
class TLSSocketFactory
        @Throws(KeyManagementException::class, NoSuchAlgorithmException::class, KeyStoreException::class, UnrecoverableKeyException::class)

This file has been truncated. show original

AudriusButkevicius · February 5, 2018, 6:27pm

Does it fail immediately? Things that come to mind is not performing the SSL handshake (you might not have to do it explicitly tho, depends on libraries), but you should not get to the hello part in that case. Other could be timeout, if syncthing doesn’t see a message in some amount of time, it assumes the connection is dead.

Nutomic · February 5, 2018, 6:35pm

It definitely performs the handshake, and calls HandshakeCompletedListener. And it’s not a timeout, the connection fails within a few hundred ms.

Here’s a log from the Android site

AudriusButkevicius · February 5, 2018, 7:12pm

You are sending index messages before cluster config, that should cause us to abort, as first message needs to be hello, followed by cluster config, followed by whatever. Also first index message needs to be Index, all others need to be IndexUpdate (for no good reason).

AudriusButkevicius · February 5, 2018, 7:16pm

github.com

syncthing/syncthing/blob/master/lib/protocol/protocol.go#L307


			return err
		}


		switch msg := msg.(type) {
		case *ClusterConfig:
			l.Debugln("read ClusterConfig message")
			if state != stateInitial {
				return fmt.Errorf("protocol error: cluster config message in state %d", state)
			}
			c.receiver.ClusterConfig(c.id, *msg)
			state = stateReady


		case *Index:
			l.Debugln("read Index message")
			if state != stateReady {
				return fmt.Errorf("protocol error: index message in state %d", state)
			}
			if err := checkIndexConsistency(msg.Files); err != nil {
				return fmt.Errorf("protocol error: index: %v", err)
			}
			c.handleIndex(*msg)

There is some noop code modifying state in other messages (yet there is a precondition that makes it pointless).

Nutomic · February 5, 2018, 7:20pm

Wouldn’t I get the error message protocol error: index message in state %d in that case? I have STTRACE=protocol set and I don’t see that message.

Also, the logs seem to be unclear in that case, it looks like it only sets the index info for the cluster config.

github.com

Nutomic/syncthing-java/blob/master/bep/src/main/kotlin/net/syncthing/java/bep/ConnectionHandler.kt#L147


    }
    run {
        //other device
        val deviceBuilder = Device.newBuilder()
                .setId(ByteString.copyFrom(DeviceId(address.deviceId).toHashData()))
        val indexSequenceInfo = indexHandler.indexRepository.findIndexInfoByDeviceAndFolder(address.deviceId(), folder.folderId)
        indexSequenceInfo?.let {
            deviceBuilder
                    .setIndexId(indexSequenceInfo.indexId)
                    .setMaxSequence(indexSequenceInfo.localSequence)
            logger.info("send delta index info device = {} index = {} max (local) sequence = {}",
                    indexSequenceInfo.deviceId,
                    indexSequenceInfo.indexId,
                    indexSequenceInfo.localSequence)
        }
        folderBuilder.addDevices(deviceBuilder)
    }
    clusterConfigBuilder.addFolders(folderBuilder)
    //TODO other devices??
}
sendMessage(clusterConfigBuilder.build())

AudriusButkevicius · February 5, 2018, 7:44pm

I am afraid the return value of that might be discarded or something like that. It would be best if you could capture the bytes you send, so that we could feed the same into the protocol package.

I for some reason don’t think it’s related to TLS. You could create a simple Go program that echoes back whatever is sent and then try to send stuff from your library, to validate that it’s not TLS.

Nutomic · February 6, 2018, 5:05am

Okay this is the data sent from the Android side, in hex format (without the TLS handshake):

2ea7d90b00220a0b4c4745204e657875732035120e73796e637468696e672d6a6176611a03302e30000408001000000000790a770a04746573741204746573748201360a20de66bae146e6569ec3efcf2d645036000a50a47123a2d0864875f45aef77d11230b0cccbb3a1ecb1927b40f1bdb0cbed96daec0282012f0a20ac3dd7974f5c30769b973c1ce7df5c1be295f991a5a38c9d59dc91c29dd5d9fa30c40740a09498adc5a8c3cb7e

Should be the hello message and cluster config.

calmh · February 6, 2018, 6:17am

Your original two log lines from Syncthing indicate it thinks the connection was closed from the other side during the handshake. Maybe the handshake includes the hello exchange, I don’t remember.

Nutomic · February 6, 2018, 6:29am

The socket is definitely not closed on the Android side.

I also tried to connect to a listening socket that echos all data back, and that worked fine (I had TLS disabled for that).

calmh · February 6, 2018, 10:28am

I don’t know. Your hello message looks fine as far as the magic and length, and then I’m not going to parse protobuf in my head any further. There used to be a really low level protocol trace option in Syncthing but I don’t think there is any more. If you add this diff you’ll see all reads and writes above TLS and maybe that makes sense of things:

--- a/lib/connections/structs.go
+++ b/lib/connections/structs.go
@@ -8,6 +8,7 @@ package connections
 
 import (
 	"crypto/tls"
+	"encoding/hex"
 	"fmt"
 	"io"
 	"net"
@@ -47,6 +48,17 @@ type internalConn struct {
 	priority int
 }
 
+func (c internalConn) Write(data []byte) (int, error) {
+	n, err := c.Conn.Write(data)
+	fmt.Printf(">>> WROTE %d bytes (err=%v)\n%s\n", n, err, hex.Dump(data[:n]))
+	return n, err
+}
+
+func (c internalConn) Read(data []byte) (int, error) {
+	n, err := c.Conn.Read(data)
+	fmt.Printf("<<< READ %d bytes (err=%v)\n%s\n", n, err, hex.Dump(data[:n]))
+	return n, err
+}
+
 type connType int
 
 const (

In a healthy setup you should see something like:

>>> WROTE 65 bytes (err=<nil>)
00000000  2e a7 d9 0b 00 3b 0a 02  73 31 12 09 73 79 6e 63  |.....;..s1..sync|
00000010  74 68 69 6e 67 1a 2a 76  30 2e 31 34 2e 34 34 2d  |thing.*v0.14.44-|
00000020  72 63 2e 32 2b 33 33 2d  67 36 33 36 31 34 37 31  |rc.2+33-g6361471|
00000030  63 2d 64 69 72 74 79 2d  76 61 72 62 6c 6f 63 6b  |c-dirty-varblock|
00000040  73                                                |s|

(that's the outgoing hello)

<<< READ 4 bytes (err=<nil>)
00000000  2e a7 d9 0b                                       |....|

(incoming read of magic)

<<< READ 2 bytes (err=<nil>)
00000000  00 19                                             |..|

(incoming read of length)

<<< READ 25 bytes (err=<nil>)
00000000  0a 02 73 32 12 09 73 79  6e 63 74 68 69 6e 67 1a  |..s2..syncthing.|
00000010  08 76 30 2e 31 34 2e 34  33                       |.v0.14.43|

(incoming read of hello)

[I6KAH] 11:26:22 INFO: Established secure connection to MRIW7OK-NETT3M4-N6SBWME-N25O76W-YJKVXPH-FUMQJ3S-P57B74J-GBITBAC at 127.0.0.1:49331-127.0.0.1:22002/tcp-client (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)

(at this point we've accepted the connection)

If that’s useful to you we can add it as an actual trace option for the future.

calmh · February 6, 2018, 10:43am

A couple of test cases to read your data works as well, so it seems well formed.

$ go test -v -run Nutom
=== RUN   TestNutomicHello
--- PASS: TestNutomicHello (0.00s)
	hello_test.go:166: protocol.HelloResult{DeviceName:"LGE Nexus 5", ClientName:"syncthing-java", ClientVersion:"0.0"}
=== RUN   TestNutomicMsg
--- PASS: TestNutomicMsg (0.00s)
	hello_test.go:181: &protocol.ClusterConfig{Folders:[]protocol.Folder{protocol.Folder{ID:"test", Label:"test", ReadOnly:false, IgnorePermissions:false, IgnoreDelete:false, DisableTempIndexes:false, Paused:false, Devices:[]protocol.Device{protocol.Device{ID:3ZTLVYK-G4ZLJ5E-Q7PZ4WW-IUBWAAU-FFBJDRE-ORNBBSY-IOX2FV3-3X2EJAM, Name:"", Addresses:[]string(nil), Compression:"METADATA", CertName:"", MaxSequence:8873436389924070960, Introducer:false, IndexID:0x2d968b6d96c1ef1, SkipIntroductionRemovals:false}, protocol.Device{ID:VQ65PF2-PLQYHNB-G4XHQOO-PX24DPH-RJL6MRU-WRYZHKS-Z3SI4FH-OV3H5AX, Name:"", Addresses:[]string(nil), Compression:"METADATA", CertName:"", MaxSequence:964, Introducer:false, IndexID:0x7e970d4455a60a20, SkipIntroductionRemovals:false}}}}}
PASS
ok  	github.com/syncthing/syncthing/lib/protocol	0.134s

Nutomic · February 6, 2018, 3:46pm

One thing I forgot to mention: sometimes connections do work, but this seems random. So when they go through, the logging looks fine. But when they fail, the error seems to happen before your logging patch is invoked. Here is the log:

[UIR6A] DEBUG: close due to reading length: EOF
[UIR6A] INFO: Connection to 3ZTLVYK-G4ZLJ5E-Q7PZ4WW-IUBWAAU-FFBJDRE-ORNBBSY-IOX2FV3-3X2EJAM closed: reading length: EOF
[UIR6A] DEBUG: Listen (BEP/tcp): connect from 172.30.1.26:53159
[UIR6A] INFO: Listen (BEP/tcp): TLS handshake: EOF
[UIR6A] DEBUG: Listen (BEP/tcp): connect from 172.30.1.254:45662
[UIR6A] INFO: Listen (BEP/tcp): TLS handshake: EOF
[UIR6A] DEBUG: Reconnect loop
[UIR6A] DEBUG: Reconnect loop for 3ZTLVYK-G4ZLJ5E-Q7PZ4WW-IUBWAAU-FFBJDRE-ORNBBSY-IOX2FV3-3X2EJAM []
[UIR6A] DEBUG: sleep until next dial 1m0s
[UIR6A] DEBUG: Listen (BEP/tcp): connect from 172.30.1.254:39378
[UIR6A] INFO: Listen (BEP/tcp): TLS handshake: EOF
[UIR6A] DEBUG: Listen (BEP/tcp): connect from 172.30.1.254:45082
[UIR6A] INFO: Listen (BEP/tcp): TLS handshake: EOF
[UIR6A] DEBUG: Listen (BEP/tcp): connect from 172.30.1.254:45162
[UIR6A] INFO: Peer 172.30.1.254:45162 did not negotiate bep/1.0
>>> WROTE 42 bytes (err=<nil>)
00000000  2e a7 d9 0b 00 24 0a 07  4c 47 2d 48 38 31 35 12  |.....$..LG-H815.|
00000010  09 73 79 6e 63 74 68 69  6e 67 1a 0e 76 30 2e 31  |.syncthing..v0.1|
00000020  34 2e 34 33 2d 64 69 72  74 79                    |4.43-dirty|

<<< READ 4 bytes (err=<nil>)
00000000  2e a7 d9 0b                                       |....|

<<< READ 2 bytes (err=<nil>)
00000000  00 22                                             |."|

<<< READ 34 bytes (err=<nil>)
00000000  0a 0b 4c 47 45 20 4e 65  78 75 73 20 35 12 0e 73  |..LGE Nexus 5..s|
00000010  79 6e 63 74 68 69 6e 67  2d 6a 61 76 61 1a 03 30  |yncthing-java..0|
00000020  2e 30                                             |.0|

[UIR6A] INFO: Established secure connection to 3ZTLVYK-G4ZLJ5E-Q7PZ4WW-IUBWAAU-FFBJDRE-ORNBBSY-IOX2FV3-3X2EJAM at 172.30.1.19:33008-172.30.1.254:45162 (tcp-server) (TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256)
[UIR6A] INFO: Device 3ZTLVYK-G4ZLJ5E-Q7PZ4WW-IUBWAAU-FFBJDRE-ORNBBSY-IOX2FV3-3X2EJAM client is "syncthing-java 0.0" named "LGE Nexus 5"
>>> WROTE 6 bytes (err=<nil>)
00000000  00 00 00 00 00 00                                 |......|

[UIR6A] DEBUG: wrote 6 bytes on the wire (2 bytes length, 0 bytes header, 4 bytes message length, 0 bytes message), err=<nil>
<<< READ 2 bytes (err=<nil>)
00000000  00 04                                             |..|

<<< READ 4 bytes (err=<nil>)
00000000  08 00 10 00                                       |....|

<<< READ 4 bytes (err=<nil>)
00000000  00 00 00 6c                                       |...l|

<<< READ 108 bytes (err=<nil>)
00000000  0a 6a 0a 04 74 65 73 74  12 04 74 65 73 74 82 01  |.j..test..test..|
00000010  36 0a 20 de 66 ba e1 46  e6 56 9e c3 ef cf 2d 64  |6. .f..F.V....-d|
00000020  50 36 00 0a 50 a4 71 23  a2 d0 86 48 75 f4 5a ef  |P6..P.q#...Hu.Z.|
00000030  77 d1 12 30 b0 cc cb b3  a1 ec b1 92 7b 40 f1 bd  |w..0........{@..|
00000040  b0 cb ed 96 da ec 02 82  01 22 0a 20 a2 23 e0 12  |.........". .#..|
00000050  2c 65 bb 55 59 37 8f b9  47 b0 8b 6f 3f 2d 24 4e  |,e.UY7..G..o?-$N|
00000060  ad f3 7d 7f 7a 74 65 72  67 03 70 6d              |..}.zterg.pm|

[UIR6A] DEBUG: read ClusterConfig message

Maybe it would help if you give it a try yourself, here is an apk with some extra logging: syncthing-lite-debug.apk (6.3 MB)

calmh · February 6, 2018, 4:25pm

I can do nothing with the apk…

The “TLS handshake: EOF” should mean literally that your side closed the connection during the handshake. Wireshark it to be sure.

Nutomic · February 6, 2018, 4:32pm

I tried to use Wireshark already, but I have no idea how to use it.

You could also run the java client directly on your pc:

git clone https://github.com/Nutomic/syncthing-java.git
git checkout listen-for-connections
./gradlew syncthing-java:run -Pargs="-a peer-device-address"
./gradlew syncthing-java:run -Pargs="-L"

By the way, running that gives me SocketException: Connection closed by remote host.

Edit: Make sure you stop any Syncthing instances on the same host, and use a peer on a different host. Otherwise it might have trouble with the discovery.

AudriusButkevicius · February 6, 2018, 4:41pm

I’ll try it this evening.

AudriusButkevicius · February 6, 2018, 8:06pm

FAILURE: Build failed with an exception.

* What went wrong:
Project 'syncthing-java' not found in root project 'a-sync'.

AudriusButkevicius · February 6, 2018, 8:12pm

c:\Go\src\github.com\Nutomic\a-sync>gradlew tasks --all | grep run
All tasks runnable from root project
tasks - Displays the tasks runnable from root project 'a-sync' (some of the displayed tasks may belong to subprojects).
a-sync-parent:tasks - Displays the tasks runnable from project ':a-sync-parent' (some of the displayed tasks may belong to subprojects).
a-sync-parent:a-sync-bep:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-bep'.
a-sync-parent:a-sync-client:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-client'.
a-sync-parent:a-sync-core:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-core'.
a-sync-parent:a-sync-discovery:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-discovery'.
a-sync-parent:a-sync-http-relay:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-http-relay'.
a-sync-parent:a-sync-http-relay-server:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-http-relay-server'.
a-sync-parent:a-sync-relay:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-relay'.
a-sync-parent:a-sync-repository:tasks - Displays the tasks runnable from project ':a-sync-parent:a-sync-repository'.

Seems there is no run task.

imsodin · February 6, 2018, 8:21pm

You seem to be on the wrong/outdated project. The libraries aren’t called “a-sync-…” anymore. For current master of https://github.com/Nutomic/syncthing-java and the same command I get

All tasks runnable from root project
discovery:run - Runs this project as a JVM application
syncthing-java:run - Runs this project as a JVM application
tasks - Displays the tasks runnable from root project 'syncthing-java' (some of the displayed tasks may belong to subprojects).
bep:tasks - Displays the tasks runnable from project ':bep'.
core:tasks - Displays the tasks runnable from project ':core'.
discovery:tasks - Displays the tasks runnable from project ':discovery'.
http-relay:tasks - Displays the tasks runnable from project ':http-relay'.
relay:tasks - Displays the tasks runnable from project ':relay'.
repository:tasks - Displays the tasks runnable from project ':repository'.
syncthing-java:tasks - Displays the tasks runnable from project ':syncthing-java'.
discovery:startScripts - Creates OS specific scripts to run the project as a JVM application.
syncthing-java:startScripts - Creates OS specific scripts to run the project as a JVM application.

AudriusButkevicius · February 6, 2018, 8:22pm

c:\Go\bin\src\github.com\Nutomic\a-sync>git show -1 -q
commit 35ce5fd9a416bf5431a8a0c8b8199d302c48ebfc (HEAD -> listen-for-connections, origin/listen-for-connections)
Author: Felix Ableitner <me@nutomic.com>
Date:   Thu Dec 21 22:56:42 2017 +0900

    WIP: listen for local discovery connections

c:\Go\bin\src\github.com\Nutomic\a-sync>git branch
* listen-for-connections
  master

c:\Go\bin\src\github.com\Nutomic\a-sync>git status
On branch listen-for-connections
Your branch is up to date with 'origin/listen-for-connections'.

nothing to commit, working tree clean

c:\Go\bin\src\github.com\Nutomic\a-sync>