From a47c6483b2e748351a5e0b9eac728674cdfce41f Mon Sep 17 00:00:00 2001 From: Spike Curtis Date: Mon, 9 Oct 2023 16:05:53 +0400 Subject: [PATCH 1/2] Log DERP connection logic and overlarge frame head Signed-off-by: Spike Curtis --- derp/derp_client.go | 8 ++++++++ derp/derphttp/derphttp_client.go | 9 +++++++-- 2 files changed, 15 insertions(+), 2 deletions(-) diff --git a/derp/derp_client.go b/derp/derp_client.go index 3b7386590a776..107aee87876af 100644 --- 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 index 4acf906a98fed..b9d175619d65a 100644 --- 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,6 +557,7 @@ 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 @@ -563,6 +565,7 @@ func (c *Client) connect(ctx context.Context, caller string) (client *derp.Clien // 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 From 3cbc3a476e1e8ec87b8edf9a68f1ac8d7e27be72 Mon Sep 17 00:00:00 2001 From: Spike Curtis Date: Mon, 30 Oct 2023 15:56:09 +0400 Subject: [PATCH 2/2] Log buffered data only Signed-off-by: Spike Curtis --- derp/derp_client.go | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/derp/derp_client.go b/derp/derp_client.go index 107aee87876af..dcc72f1133f83 100644 --- a/derp/derp_client.go +++ b/derp/derp_client.go @@ -478,14 +478,19 @@ 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) + // This could be due to some middleware returning non-DERP data. Read whatever we have + // buffered + bufd := c.br.Buffered() + raw := make([]byte, 5, 5+bufd) 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) + nd, err := c.br.Peek(bufd) + if err != nil { + c.logf("[unexpected] large or corrupt frame; failed to read buffered bytes") + return nil, fmt.Errorf("unexpectedly large frame (type 0x%x) of %d bytes returned", t, n) + } + raw = append(raw, nd...) + c.logf("[unexpected] large or corrupt frame; up to buffered bytes as follows: %q", raw) return nil, fmt.Errorf("unexpectedly large frame (type 0x%x) of %d bytes returned", t, n) }