Sporadic EOF while reading (interop with NSS)

[Lekensteyn]

After adding NSS to the interop tests for #43, the client test sporadically fail (or sporadically succeed 😉 ). The client (_dev/tris-testclient/client.go) is executed against the NSS test server (_dev/tstclnt/server.sh). For some reason it only happens with the TLS 1.2 test, the three following TLS 1.3 tests have no issue. I have not seen the issue with boringssl before.

While trying to track this down, the following message is visible in the travis logs (the "Failed handshakes" line is out of order due to stdout vs stderr, from this build):

+docker run --rm tris-testclient -ecdsa=false 172.17.0.3:1443
TLS 1.2 with TLS_RSA_WITH_AES_128_CBC_SHA
Read failed: EOF

TLS 1.3 with TLS_CHACHA20_POLY1305_SHA256
Read 154 bytes
OK

TLS 1.3 with TLS_AES_128_GCM_SHA256
Read 154 bytes
OK

TLS 1.3 with TLS_AES_256_GCM_SHA384
2017/12/05 14:40:29 Failed handshakes: 1
Read 154 bytes
OK

In another build with pcap+keylog enabled (original log: log-005.txt, commit a8d4e4d, branch pwu/travis), it failed in the second run:

+docker run --rm tris-testclient -rsa=false 172.17.0.3:2443
TLS 1.2 with TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
Read failed: EOF

TLS 1.3 with TLS_CHACHA20_POLY1305_SHA256
Read 154 bytes
OK

TLS 1.3 with TLS_AES_128_GCM_SHA256
Read 154 bytes
OK

TLS 1.3 with TLS_AES_256_GCM_SHA384
2017/12/05 14:49:17 Failed handshakes: 1
Read 154 bytes
OK

++echo ERR: 1

In tcp.stream==4 of 005.tar.gz, the server sends application data, close_notify and TCP FIN. The client also sends a close_notify but receives a TCP RST. (In stream 0 where the test passes, the client is earlier with sending its close_notify and FIN/ACK and the server (selfserv) receives a TCP RST instead.)

Restarting this build has these results:

• 005 - failure in second run (above)
• 006 - success (006.tar.gz, log-006.txt)
• 007 - failure in first run (007.tar.gz, log-007.txt)
• 008 - failure in second run (008.tar.gz, log-008.txt)

Possibly related issue with the same cause: golang/go#19874

---

Actually the minimum reproducer seems to be the program below.

mkdir certdb
certutil -d certdb -N --empty-password
certutil -d certdb -S -n rsa-server -t u -x -s CN=localhost -k rsa -z /dev/null
selfserv -n rsa-server   -p 1443 -d certdb -V tls1.2:tls1.3 -v -Z
go run main.go

Output using upstream go version go1.9.2 darwin/amd64 (most of the time this fails the first handshake, but sometimes it fails the second):

2017/12/05 16:05:18 Read 154 bytes
2017/12/05 16:05:18 Read failed: EOF

2017/12/05 16:05:18 Failed handshake: 1
exit status 1

Changing the read buffer size to something smaller (e.g. "1") seems to avoid the issue. Perhaps it should not return EOF when some data is already read (i.e. a partial read).

main.go:

package main

import (
	"crypto/tls"
	"fmt"
	"io"
	"log"
	"os"
	"strings"
)

func poke(addr string, keylog io.Writer) error {
	tls_config := &tls.Config{
		InsecureSkipVerify: true,
		MinVersion:         tls.VersionTLS12,
		MaxVersion:         tls.VersionTLS12,
		KeyLogWriter:       keylog,
	}
	con, err := tls.Dial("tcp", addr, tls_config)
	if err != nil {
		log.Printf("handshake failed: %v\n\n", err)
		return err
	}
	defer con.Close()

	_, err = con.Write([]byte("GET / HTTP/1.1\r\nHost: localhost\r\n\r\n"))
	if err != nil {
		log.Printf("Write failed: %v\n\n", err)
		return err
	}

	buf := make([]byte, 1024)
	n, err := con.Read(buf)
	if err != nil {
		log.Printf("Read failed: %v\n\n", err)
		return err
	}
	log.Printf("Read %d bytes\n", n)
	return nil
}

func main() {
	if len(os.Args) != 2 {
		fmt.Printf("Usage: %s host[:port]\nDefaults to port 443\n", os.Args[0])
		os.Exit(1)
	}
	addr := os.Args[1]
	if !strings.Contains(addr, ":") {
		addr += ":443"
	}

	var keylog io.Writer
	if keylog_file := os.Getenv("SSLKEYLOGFILE"); keylog_file != "" {
		var err error
		keylog, err = os.OpenFile(keylog_file, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0600)
		if err != nil {
			log.Fatalf("Cannot open keylog file: %v", err)
		}
		log.Println("Enabled keylog")
	}

	for i := 0; i < 100; i++ {
		if err := poke(addr, keylog); err != nil {
			log.Fatalf("Failed handshake: %d\n", i)
		}
	}

	log.Println("All handshakes passed")
}

[Lekensteyn]

And apparently this is by design... Need to check the returned length rather than error. From conn.go:

		// If a close-notify alert is waiting, read it so that
		// we can return (n, EOF) instead of (n, nil), to signal
		// to the HTTP response reading goroutine that the
		// connection is now closed. [..]

[Lekensteyn]

Fix merged into master, closing.