Log DERP connection logic and overlarge frame head

spikecurtis · spikecurtis · commit a47c6483b2e7 · 2023-10-09T16:05:53.000+04:00
Signed-off-by: Spike Curtis &lt;spike@coder.com&gt;
diff --git a/derp/derp_client.go b/derp/derp_client.go
@@ -478,6 +478,14 @@ func (c *Client) recvTimeout(timeout time.Duration) (m ReceivedMessage, err erro
 			return nil, err
 		}
 		if n > 1<<20 {
+			// This could be due to some middleware returning non-DERP data.  Read a little more of
+			// the stream and log for debugging before throwing an error.
+			raw := make([]byte, 256)
+			raw[0] = byte(t)
+			bin.PutUint32(raw[1:5], n)
+			k, _ := c.br.Read(raw[5:])
+			raw = raw[:5+k]
+			c.logf("[unexpected] large or corrupt frame; up to 256 bytes as follows: %q", raw)
 			return nil, fmt.Errorf("unexpectedly large frame (type 0x%x) of %d bytes returned", t, n)
 		}
 
diff --git a/derp/derphttp/derphttp_client.go b/derp/derphttp/derphttp_client.go
@@ -518,8 +518,9 @@ func (c *Client) connect(ctx context.Context, caller string) (client *derp.Clien
 		// https://blog.gypsyengineer.com/en/security/how-does-tls-1-3-protect-against-downgrade-attacks.html
 		cs := tlsConn.ConnectionState()
 		tlsState = &cs
+		c.logf("%s: TLS version 0x%x", caller, cs.Version)
 		if cs.Version >= tls.VersionTLS13 {
-			serverPub, serverProtoVersion = parseMetaCert(cs.PeerCertificates)
+			serverPub, serverProtoVersion = parseMetaCert(c.logf, cs.PeerCertificates)
 		}
 	} else {
 		httpConn = tcpConn
@@ -556,13 +557,15 @@ func (c *Client) connect(ctx context.Context, caller string) (client *derp.Clien
 		// just to get routed into the server's HTTP Handler so it
 		// can Hijack the request, but we signal with a special header
 		// that we don't want to deal with its HTTP response.
+		c.logf("%s: using fast start", caller)
 		req.Header.Set(fastStartHeader, "1") // suppresses the server's HTTP response
 		if err := req.Write(brw); err != nil {
 			return nil, 0, err
 		}
 		// No need to flush the HTTP request. the derp.Client's initial
 		// client auth frame will flush it.
 	} else {
+		c.logf("%s: not using fast start", caller)
 		if err := req.Write(brw); err != nil {
 			return nil, 0, err
 		}
@@ -574,6 +577,7 @@ func (c *Client) connect(ctx context.Context, caller string) (client *derp.Clien
 		if err != nil {
 			return nil, 0, err
 		}
+		c.logf("%s: DERP server returned status %d", caller, resp.StatusCode)
 		if resp.StatusCode != http.StatusSwitchingProtocols {
 			b, _ := io.ReadAll(resp.Body)
 			resp.Body.Close()
@@ -1206,8 +1210,9 @@ func (c *Client) closeForReconnect(brokenClient *derp.Client) {
 
 var ErrClientClosed = errors.New("derphttp.Client closed")
 
-func parseMetaCert(certs []*x509.Certificate) (serverPub key.NodePublic, serverProtoVersion int) {
+func parseMetaCert(logf logger.Logf, certs []*x509.Certificate) (serverPub key.NodePublic, serverProtoVersion int) {
 	for _, cert := range certs {
+		logf("derpclient: got cert %s", cert.Subject.CommonName)
 		// Look for derpkey prefix added by initMetacert() on the server side.
 		if pubHex, ok := strings.CutPrefix(cert.Subject.CommonName, "derpkey"); ok {
 			var err error

Original file line number	Diff line number	Diff line change
`@@ -478,6 +478,14 @@ func (c *Client) recvTimeout(timeout time.Duration) (m ReceivedMessage, err erro`
`478`	`478`	`return nil, err`
`479`	`479`	`}`
`480`	`480`	`if n > 1<<20 {`
	`481`	`+ // This could be due to some middleware returning non-DERP data. Read a little more of`
	`482`	`+ // the stream and log for debugging before throwing an error.`
	`483`	`+ raw := make([]byte, 256)`
	`484`	`+ raw[0] = byte(t)`
	`485`	`+ bin.PutUint32(raw[1:5], n)`
	`486`	`+ k, _ := c.br.Read(raw[5:])`
	`487`	`+ raw = raw[:5+k]`
	`488`	`+ c.logf("[unexpected] large or corrupt frame; up to 256 bytes as follows: %q", raw)`
`481`	`489`	`return nil, fmt.Errorf("unexpectedly large frame (type 0x%x) of %d bytes returned", t, n)`
`482`	`490`	`}`
`483`	`491`