Add command line arg for enabling debug logs

Log debugs for frame and packet reading to diagnose high CPU

cmd/mc-router/main.go

@@ -23,6 +23,7 @@ var (
 	kubeConfigFile = flag.String("kube-config", "", "The path to a kubernetes configuration file")
 	inKubeCluster  = flag.Bool("in-kube-cluster", false, "Use in-cluster kubernetes config")
 	cpuProfile     = flag.String("cpu-profile", "", "Enables CPU profiling and writes to given path")
+	debug          = flag.Bool("debug", false, "Enable debug logs")
 )
 
 var (
@@ -43,6 +44,11 @@ func main() {
 		os.Exit(0)
 	}
 
+	if *debug {
+		logrus.SetLevel(logrus.DebugLevel)
+		logrus.Debug("Debug logs enabled")
+	}
+
 	if *cpuProfile != "" {
 		cpuProfileFile, err := os.Create(*cpuProfile)
 		if err != nil {
@@ -50,7 +56,7 @@ func main() {
 		}
 		defer cpuProfileFile.Close()
 
-		logrus.WithField("file", *cpuProfileFile).Info("Starting cpu profiling")
+		logrus.WithField("file", *cpuProfile).Info("Starting cpu profiling")
 		err = pprof.StartCPUProfile(cpuProfileFile)
 		if err != nil {
 			logrus.WithError(err).Fatal("trying to start cpu profile")

mcproto/read.go

@@ -0,0 +1,171 @@
+package mcproto
+
+import (
+	"bytes"
+	"errors"
+	"github.com/sirupsen/logrus"
+	"io"
+	"net"
+	"strings"
+)
+
+func ReadPacket(reader io.Reader, addr net.Addr) (*Packet, error) {
+	logrus.
+		WithField("client", addr).
+		Debug("Reading packet")
+
+	frame, err := ReadFrame(reader, addr)
+	if err != nil {
+		return nil, err
+	}
+
+	packet := &Packet{Length: frame.Length}
+
+	remainder := bytes.NewBuffer(frame.Payload)
+
+	packet.PacketID, err = ReadVarInt(remainder)
+	if err != nil {
+		return nil, err
+	}
+
+	packet.Data = remainder.Bytes()
+
+	logrus.
+		WithField("client", addr).
+		WithField("packet", packet).
+		Debug("Read packet")
+	return packet, nil
+}
+
+func ReadFrame(reader io.Reader, addr net.Addr) (*Frame, error) {
+	logrus.
+		WithField("client", addr).
+		Debug("Reading frame")
+
+	var err error
+	frame := &Frame{}
+
+	frame.Length, err = ReadVarInt(reader)
+	if err != nil {
+		return nil, err
+	}
+	logrus.
+		WithField("client", addr).
+		WithField("length", frame.Length).
+		Debug("Read frame length")
+
+	frame.Payload = make([]byte, frame.Length)
+	total := 0
+	for total < frame.Length {
+		readIntoThis := frame.Payload[total:]
+		n, err := reader.Read(readIntoThis)
+		if err != nil {
+			if err != io.EOF {
+				return nil, err
+			}
+		}
+		total += n
+		logrus.
+			WithField("client", addr).
+			WithField("total", total).
+			WithField("length", frame.Length).
+			Debug("Reading frame content")
+	}
+
+	logrus.
+		WithField("client", addr).
+		WithField("frame", frame).
+		Debug("Read frame")
+	return frame, nil
+}
+
+func ReadVarInt(reader io.Reader) (int, error) {
+	b := make([]byte, 1)
+	var numRead uint = 0
+	result := 0
+	for numRead <= 5 {
+		n, err := reader.Read(b)
+		if err != nil {
+			return 0, err
+		}
+		if n == 0 {
+			continue
+		}
+		value := b[0] & 0x7F
+		result |= int(value) << (7 * numRead)
+
+		numRead++
+
+		if b[0]&0x80 == 0 {
+			return result, nil
+		}
+	}
+
+	return 0, errors.New("VarInt is too big")
+}
+
+func ReadString(reader io.Reader) (string, error) {
+	length, err := ReadVarInt(reader)
+	if err != nil {
+		return "", err
+	}
+
+	b := make([]byte, 1)
+	var strBuilder strings.Builder
+	for i := 0; i < length; i++ {
+		n, err := reader.Read(b)
+		if err != nil {
+			return "", err
+		}
+		if n == 0 {
+			continue
+		}
+		strBuilder.WriteByte(b[0])
+	}
+
+	return strBuilder.String(), nil
+}
+
+func ReadUnsignedShort(reader io.Reader) (uint16, error) {
+	upper := make([]byte, 1)
+	_, err := reader.Read(upper)
+	if err != nil {
+		return 0, err
+	}
+	lower := make([]byte, 1)
+	_, err = reader.Read(lower)
+	if err != nil {
+		return 0, err
+	}
+
+	return (uint16(upper[0]) << 8) | uint16(lower[0]), nil
+}
+
+func ReadHandshake(data []byte) (*Handshake, error) {
+
+	handshake := &Handshake{}
+	buffer := bytes.NewBuffer(data)
+	var err error
+
+	handshake.ProtocolVersion, err = ReadVarInt(buffer)
+	if err != nil {
+		return nil, err
+	}
+
+	handshake.ServerAddress, err = ReadString(buffer)
+	if err != nil {
+		return nil, err
+	}
+
+	handshake.ServerPort, err = ReadUnsignedShort(buffer)
+	if err != nil {
+		return nil, err
+	}
+
+	nextState, err := ReadVarInt(buffer)
+	if err != nil {
+		return nil, err
+	}
+	handshake.NextState = nextState
+	return handshake, nil
+}

mcproto/types.go

@@ -1,23 +1,38 @@
 package mcproto
 
-import (
+import "fmt"
-	"bytes"
-	"errors"
-	"io"
-	"strings"
-)
 
 type Frame struct {
 	Length  int
 	Payload []byte
 }
 
+var trimLimit = 64
+
+func trimBytes(data []byte) ([]byte, string) {
+	if len(data) < trimLimit {
+		return data, ""
+	} else {
+		return data[:trimLimit], "..."
+	}
+}
+
+func (f *Frame) String() string {
+	trimmed, cont := trimBytes(f.Payload)
+	return fmt.Sprintf("Frame:[len=%d, payload=%#X%s]", f.Length, trimmed, cont)
+}
+
 type Packet struct {
 	Length   int
 	PacketID int
 	Data     []byte
 }
 
+func (p *Packet) String() string {
+	trimmed, cont := trimBytes(p.Data)
+	return fmt.Sprintf("Frame:[len=%d, packetId=%d, data=%#X%s]", p.Length, p.PacketID, trimmed, cont)
+}
+
 const PacketIdHandshake = 0x00
 
 type Handshake struct {
@@ -30,140 +45,3 @@ type Handshake struct {
 type ByteReader interface {
 	ReadByte() (byte, error)
 }
-
-func ReadVarInt(reader io.Reader) (int, error) {
-	b := make([]byte, 1)
-	var numRead uint = 0
-	result := 0
-	for numRead <= 5 {
-		n, err := reader.Read(b)
-		if err != nil {
-			return 0, err
-		}
-		if n == 0 {
-			continue
-		}
-		value := b[0] & 0x7F
-		result |= int(value) << (7 * numRead)
-
-		numRead++
-
-		if b[0]&0x80 == 0 {
-			return result, nil
-		}
-	}
-
-	return 0, errors.New("VarInt is too big")
-}
-
-func ReadString(reader io.Reader) (string, error) {
-	length, err := ReadVarInt(reader)
-	if err != nil {
-		return "", err
-	}
-
-	b := make([]byte, 1)
-	var strBuilder strings.Builder
-	for i := 0; i < length; i++ {
-		n, err := reader.Read(b)
-		if err != nil {
-			return "", err
-		}
-		if n == 0 {
-			continue
-		}
-		strBuilder.WriteByte(b[0])
-	}
-
-	return strBuilder.String(), nil
-}
-
-func ReadUnsignedShort(reader io.Reader) (uint16, error) {
-	upper := make([]byte, 1)
-	_, err := reader.Read(upper)
-	if err != nil {
-		return 0, err
-	}
-	lower := make([]byte, 1)
-	_, err = reader.Read(lower)
-	if err != nil {
-		return 0, err
-	}
-
-	return (uint16(upper[0]) << 8) | uint16(lower[0]), nil
-}
-
-func ReadFrame(reader io.Reader) (*Frame, error) {
-	var err error
-	frame := &Frame{}
-
-	frame.Length, err = ReadVarInt(reader)
-	if err != nil {
-		return nil, err
-	}
-
-	frame.Payload = make([]byte, frame.Length)
-	total := 0
-	for total < frame.Length {
-		readIntoThis := frame.Payload[total:]
-		n, err := reader.Read(readIntoThis)
-		if err != nil {
-			if err != io.EOF {
-				return nil, err
-			}
-		}
-		total += n
-	}
-
-	return frame, nil
-}
-
-func ReadPacket(reader io.Reader) (*Packet, error) {
-
-	frame, err := ReadFrame(reader)
-	if err != nil {
-		return nil, err
-	}
-
-	packet := &Packet{Length: frame.Length}
-
-	remainder := bytes.NewBuffer(frame.Payload)
-
-	packet.PacketID, err = ReadVarInt(remainder)
-	if err != nil {
-		return nil, err
-	}
-
-	packet.Data = remainder.Bytes()
-
-	return packet, nil
-}
-
-func ReadHandshake(data []byte) (*Handshake, error) {
-
-	handshake := &Handshake{}
-	buffer := bytes.NewBuffer(data)
-	var err error
-
-	handshake.ProtocolVersion, err = ReadVarInt(buffer)
-	if err != nil {
-		return nil, err
-	}
-
-	handshake.ServerAddress, err = ReadString(buffer)
-	if err != nil {
-		return nil, err
-	}
-
-	handshake.ServerPort, err = ReadUnsignedShort(buffer)
-	if err != nil {
-		return nil, err
-	}
-
-	nextState, err := ReadVarInt(buffer)
-	if err != nil {
-		return nil, err
-	}
-	handshake.NextState = nextState
-	return handshake, nil
-}

server/connector.go

@@ -1,12 +1,12 @@
 package server
 
 import (
-	"net"
-	"github.com/sirupsen/logrus"
-	"github.com/itzg/mc-router/mcproto"
-	"context"
-	"io"
 	"bytes"
+	"context"
+	"github.com/itzg/mc-router/mcproto"
+	"github.com/sirupsen/logrus"
+	"io"
+	"net"
 )
 
 type IConnector interface {
@@ -61,7 +61,7 @@ func (c *connectorImpl) HandleConnection(ctx context.Context, frontendConn net.C
 
 	inspectionReader := io.TeeReader(frontendConn, inspectionBuffer)
 
-	packet, err := mcproto.ReadPacket(inspectionReader)
+	packet, err := mcproto.ReadPacket(inspectionReader, clientAddr)
 	if err != nil {
 		logrus.WithError(err).WithField("clientAddr", clientAddr).Error("Failed to read packet")
 		return