Refine logger

common/acme/acme.go

@@ -15,15 +15,15 @@ import (
 	"github.com/go-acme/lego/v4/certcrypto"
 	"github.com/go-acme/lego/v4/certificate"
 	"github.com/go-acme/lego/v4/lego"
-	"github.com/go-acme/lego/v4/log"
+	legoLog "github.com/go-acme/lego/v4/log"
 	"github.com/go-acme/lego/v4/registration"
 	"github.com/sagernet/sing/common"
 	E "github.com/sagernet/sing/common/exceptions"
-	"github.com/sirupsen/logrus"
+	"github.com/sagernet/sing/common/log"
 )
 
 func init() {
-	log.Logger = logrus.StandardLogger()
+	legoLog.Logger = log.NewLogger("acme")
 }
 
 type CertificateUpdateListener func(certificate *tls.Certificate)

common/buf/hex.go

@@ -0,0 +1,9 @@
+package buf
+
+import "encoding/hex"
+
+func EncodeHexString(src []byte) string {
+	dst := Make(hex.EncodedLen(len(src)))
+	hex.Encode(dst, src)
+	return string(dst)
+}

common/debug/debug.go

@@ -1,5 +1,5 @@
 //go:build debug
 
-package lowmem
+package debug
 
 const Enabled = true

common/debug/free.go

@@ -1,4 +1,4 @@
-package lowmem
+package debug
 
 import (
 	"runtime/debug"

common/debug/stub.go

@@ -1,5 +1,5 @@
 //go:build !debug
 
-package lowmem
+package debug
 
 const Enabled = false

common/log/log.go

@@ -1,7 +0,0 @@
-package log
-
-import "github.com/sirupsen/logrus"
-
-func init() {
-	logrus.StandardLogger().Formatter.(*logrus.TextFormatter).ForceColors = true
-}

common/log/logrus.go

@@ -0,0 +1,33 @@
+package log
+
+import (
+	"strings"
+
+	"github.com/sirupsen/logrus"
+)
+
+func init() {
+	logrus.StandardLogger().Formatter.(*logrus.TextFormatter).ForceColors = true
+	logrus.AddHook(new(TaggedHook))
+}
+
+func NewLogger(tag string) *logrus.Entry {
+	return logrus.NewEntry(logrus.StandardLogger()).WithField("tag", tag)
+}
+
+type TaggedHook struct{}
+
+func (h *TaggedHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (h *TaggedHook) Fire(entry *logrus.Entry) error {
+	if tagObj, loaded := entry.Data["tag"]; loaded {
+		tag := tagObj.(string)
+		delete(entry.Data, "tag")
+		entry.Message = strings.ReplaceAll(entry.Message, tag+": ", "")
+		entry.Message = "[" + tag + "]: " + entry.Message
+
+	}
+	return nil
+}

common/log/logrus_debug.go

@@ -0,0 +1,31 @@
+//go:build debug
+
+package log
+
+import (
+	"path/filepath"
+	"runtime"
+	"strconv"
+	"strings"
+
+	"github.com/sirupsen/logrus"
+)
+
+var basePath string
+
+func init() {
+	basePath, _ = filepath.Abs(".")
+}
+
+func init() {
+	logrus.StandardLogger().SetReportCaller(true)
+	logrus.StandardLogger().Formatter.(*logrus.TextFormatter).CallerPrettyfier = func(frame *runtime.Frame) (function string, file string) {
+		file = frame.File + ":" + strconv.Itoa(frame.Line)
+		if strings.HasPrefix(file, basePath) {
+			file = file[len(basePath)+1:]
+		}
+
+		file = " " + file
+		return
+	}
+}

protocol/shadowsocks/shadowaead_2022/protocol.go

@@ -15,7 +15,9 @@ import (
 
 	"github.com/sagernet/sing/common"
 	"github.com/sagernet/sing/common/buf"
+	"github.com/sagernet/sing/common/debug"
 	E "github.com/sagernet/sing/common/exceptions"
+	"github.com/sagernet/sing/common/log"
 	M "github.com/sagernet/sing/common/metadata"
 	"github.com/sagernet/sing/common/replay"
 	"github.com/sagernet/sing/common/rw"
@@ -47,6 +49,8 @@ const (
 	overhead = 16
 )
 
+var logger = log.NewLogger("shadowaead (2022)")
+
 var (
 	ErrBadHeaderType         = E.New("bad header type")
 	ErrBadTimestamp          = E.New("bad timestamp")
@@ -200,26 +204,54 @@ func (m *Method) writeExtendedIdentityHeaders(request *buf.Buffer, salt []byte)
 	if pskLen < 2 {
 		return
 	}
+	if debug.Enabled {
+		logger.Trace("begin extended identity headers")
+	}
 	for i, psk := range m.pskList {
+		if debug.Enabled {
+			logger.Trace("current psk ", buf.EncodeHexString(psk[:]))
+		}
+
 		keyMaterial := make([]byte, 2*KeySaltSize)
 		copy(keyMaterial, psk[:])
 		copy(keyMaterial[KeySaltSize:], salt)
 		_identitySubkey := buf.Make(m.keyLength)
 		identitySubkey := common.Dup(_identitySubkey)
 		blake3.DeriveKey(identitySubkey, "shadowsocks 2022 identity subkey", keyMaterial)
+
+		if debug.Enabled {
+			logger.Trace("identity subkey ", buf.EncodeHexString(identitySubkey))
+		}
+
 		pskHash := m.pskHash[aes.BlockSize*i : aes.BlockSize*(i+1)]
-		m.blockConstructor(identitySubkey).Encrypt(request.Extend(16), pskHash)
+		if debug.Enabled {
+			logger.Trace("next psk hash ", buf.EncodeHexString(pskHash))
+		}
+
+		header := request.Extend(16)
+		m.blockConstructor(identitySubkey).Encrypt(header, pskHash)
+		if debug.Enabled {
+			logger.Trace("encoded ", buf.EncodeHexString(header))
+		}
 		if i == pskLen-2 {
 			break
 		}
 	}
+	if debug.Enabled {
+		logger.Trace("ended extended identity headers")
+	}
 }
 
 func (c *clientConn) writeRequest(payload []byte) error {
+	if debug.Enabled {
+		logger.Trace("begin client handshake request")
+	}
+
 	salt := make([]byte, KeySaltSize)
 	common.Must1(io.ReadFull(c.method.secureRNG, salt))
 
 	key := Blake3DeriveKey(c.method.psk[:], salt, c.method.keyLength)
+
 	writer := shadowaead.NewWriter(
 		c.Conn,
 		c.method.constructor(common.Dup(key)),
@@ -241,6 +273,10 @@ func (c *clientConn) writeRequest(payload []byte) error {
 	}
 
 	if len(payload) > 0 {
+		if debug.Enabled {
+			logger.Trace("write payload ", len(payload), "B")
+		}
+
 		err = binary.Write(bufferedWriter, binary.BigEndian, uint16(0))
 		if err != nil {
 			return E.Cause(err, "write padding length")
@@ -251,6 +287,9 @@ func (c *clientConn) writeRequest(payload []byte) error {
 		}
 	} else {
 		pLen := rand.Intn(MaxPaddingLength + 1)
+		if debug.Enabled {
+			logger.Trace("write padding ", pLen, "B")
+		}
 		err = binary.Write(bufferedWriter, binary.BigEndian, uint16(pLen))
 		if err != nil {
 			return E.Cause(err, "write padding length")
@@ -266,6 +305,10 @@ func (c *clientConn) writeRequest(payload []byte) error {
 		return E.Cause(err, "client handshake")
 	}
 
+	if debug.Enabled {
+		logger.Trace("ended client handshake request")
+	}
+
 	c.requestSalt = salt
 	c.writer = writer
 	return nil
@@ -283,6 +326,10 @@ func (c *clientConn) readResponse() error {
 		return nil
 	}
 
+	if debug.Enabled {
+		logger.Trace("begin client handshake response")
+	}
+
 	_salt := make([]byte, KeySaltSize)
 	salt := common.Dup(_salt)
 	_, err := io.ReadFull(c.Conn, salt)
@@ -291,6 +338,7 @@ func (c *clientConn) readResponse() error {
 	}
 
 	if !c.method.replayFilter.Check(salt) {
+		logger.Warn("read salt ", buf.EncodeHexString(salt))
 		return E.New("salt not unique")
 	}
 
@@ -314,7 +362,11 @@ func (c *clientConn) readResponse() error {
 	if err != nil {
 		return err
 	}
+
 	if math.Abs(float64(time.Now().Unix()-int64(epoch))) > 30 {
+		if debug.Enabled {
+			logger.Trace("server timestamp ", time.Unix(int64(epoch), 0).String())
+		}
 		return ErrBadTimestamp
 	}
 
@@ -326,11 +378,18 @@ func (c *clientConn) readResponse() error {
 	}
 
 	if bytes.Compare(requestSalt, c.requestSalt) > 0 {
+		if debug.Enabled {
+			logger.Trace("request salt ", buf.EncodeHexString(requestSalt))
+		}
 		return ErrBadRequestSalt
 	}
 
 	c.requestSalt = nil
 	c.reader = reader
+
+	if debug.Enabled {
+		logger.Trace("ended client handshake response")
+	}
 	return nil
 }
 
@@ -345,6 +404,7 @@ func (c *clientConn) WriteTo(w io.Writer) (n int64, err error) {
 	if err = c.readResponse(); err != nil {
 		return
 	}
+
 	return c.reader.WriteTo(w)
 }
 
@@ -406,6 +466,10 @@ type clientPacketConn struct {
 }
 
 func (c *clientPacketConn) WritePacket(buffer *buf.Buffer, destination *M.AddrPort) error {
+	if debug.Enabled {
+		logger.Trace("begin client packet")
+	}
+
 	defer buffer.Release()
 	_header := buf.StackNew()
 	header := common.Dup(_header)
@@ -421,24 +485,49 @@ func (c *clientPacketConn) WritePacket(buffer *buf.Buffer, destination *M.AddrPo
 		dataIndex = aes.BlockSize
 	}
 
+	packetId := c.session.nextPacketId()
+
+	if debug.Enabled {
+		logger.Trace("session id ", c.session.sessionId)
+		logger.Trace("packet id ", packetId)
+	}
+
 	common.Must(
 		binary.Write(header, binary.BigEndian, c.session.sessionId),
-		binary.Write(header, binary.BigEndian, c.session.nextPacketId()),
+		binary.Write(header, binary.BigEndian, packetId),
 	)
 
 	if c.method.udpCipher == nil && pskLen > 1 {
+		if debug.Enabled {
+			logger.Trace("begin extended identity headers")
+		}
 		for i, psk := range c.method.pskList {
+			if debug.Enabled {
+				logger.Trace("current psk ", buf.EncodeHexString(psk[:]))
+			}
+
 			dataIndex += aes.BlockSize
 			pskHash := c.method.pskHash[aes.BlockSize*i : aes.BlockSize*(i+1)]
+			if debug.Enabled {
+				logger.Trace("next psk hash ", buf.EncodeHexString(pskHash))
+			}
+
 			identityHeader := header.Extend(aes.BlockSize)
 			for textI := 0; textI < aes.BlockSize; textI++ {
 				identityHeader[textI] = pskHash[textI] ^ header.Byte(textI)
 			}
 			c.method.blockConstructor(psk[:]).Encrypt(identityHeader, identityHeader)
+			if debug.Enabled {
+				logger.Trace("encoded ", buf.EncodeHexString(identityHeader))
+			}
+
 			if i == pskLen-2 {
 				break
 			}
 		}
+		if debug.Enabled {
+			logger.Trace("end extended identity headers")
+		}
 	}
 	common.Must(
 		header.WriteByte(HeaderTypeClient),
@@ -462,6 +551,7 @@ func (c *clientPacketConn) WritePacket(buffer *buf.Buffer, destination *M.AddrPo
 		buffer.Extend(c.session.cipher.Overhead())
 		c.method.udpBlockCipher.Encrypt(packetHeader, packetHeader)
 	}
+	logger.Trace("ended client packet")
 	return common.Error(c.Write(buffer.Bytes()))
 }
 

protocol/shadowsocks/shadowaead_2022/service.go

@@ -15,6 +15,7 @@ import (
 	"github.com/sagernet/sing/common"
 	"github.com/sagernet/sing/common/buf"
 	"github.com/sagernet/sing/common/cache"
+	"github.com/sagernet/sing/common/debug"
 	E "github.com/sagernet/sing/common/exceptions"
 	M "github.com/sagernet/sing/common/metadata"
 	"github.com/sagernet/sing/common/replay"
@@ -81,12 +82,20 @@ func (s *Service) NewConnection(ctx context.Context, conn net.Conn, metadata M.M
 }
 
 func (s *Service) newConnection(ctx context.Context, conn net.Conn, metadata M.Metadata) error {
+	if debug.Enabled {
+		logger.Trace("begin server handshake request")
+	}
+
 	requestSalt := make([]byte, KeySaltSize)
 	_, err := io.ReadFull(conn, requestSalt)
 	if err != nil {
 		return E.Cause(err, "read request salt")
 	}
 
+	if debug.Enabled {
+		logger.Trace("read salt ", buf.EncodeHexString(requestSalt))
+	}
+
 	if !s.replayFilter.Check(requestSalt) {
 		return E.New("salt not unique")
 	}
@@ -112,6 +121,10 @@ func (s *Service) newConnection(ctx context.Context, conn net.Conn, metadata M.M
 	if err != nil {
 		return E.Cause(err, "read timestamp")
 	}
+	if debug.Enabled {
+		logger.Trace("client timestamp ", time.Unix(int64(epoch), 0).String())
+	}
+
 	if math.Abs(float64(time.Now().Unix()-int64(epoch))) > 30 {
 		return ErrBadTimestamp
 	}
@@ -120,6 +133,9 @@ func (s *Service) newConnection(ctx context.Context, conn net.Conn, metadata M.M
 	if err != nil {
 		return E.Cause(err, "read destination")
 	}
+	if debug.Enabled {
+		logger.Trace("destination ", destination)
+	}
 
 	var paddingLen uint16
 	err = binary.Read(reader, binary.BigEndian, &paddingLen)
@@ -127,6 +143,14 @@ func (s *Service) newConnection(ctx context.Context, conn net.Conn, metadata M.M
 		return E.Cause(err, "read padding length")
 	}
 
+	if debug.Enabled {
+		if paddingLen > 0 {
+			logger.Trace("padding ", paddingLen, "B")
+		} else {
+			logger.Trace("no padding")
+		}
+	}
+
 	if paddingLen > 0 {
 		err = reader.Discard(int(paddingLen))
 		if err != nil {
@@ -134,6 +158,10 @@ func (s *Service) newConnection(ctx context.Context, conn net.Conn, metadata M.M
 		}
 	}
 
+	if debug.Enabled {
+		logger.Trace("end server handshake request")
+	}
+
 	metadata.Protocol = "shadowsocks"
 	metadata.Destination = destination
 	return s.handler.NewConnection(ctx, &serverConn{

protocol/socks/listener.go

@@ -56,6 +56,18 @@ func HandleConnection(ctx context.Context, conn net.Conn, authenticator auth.Aut
 	if err != nil {
 		return E.Cause(err, "read socks auth request")
 	}
+	return handleConnection(authRequest, ctx, conn, authenticator, bind, handler, metadata)
+}
+
+func HandleConnection0(ctx context.Context, conn net.Conn, authenticator auth.Authenticator, bind netip.Addr, handler Handler, metadata M.Metadata) error {
+	authRequest, err := ReadAuthRequest0(conn)
+	if err != nil {
+		return E.Cause(err, "read socks auth request")
+	}
+	return handleConnection(authRequest, ctx, conn, authenticator, bind, handler, metadata)
+}
+
+func handleConnection(authRequest *AuthRequest, ctx context.Context, conn net.Conn, authenticator auth.Authenticator, bind netip.Addr, handler Handler, metadata M.Metadata) error {
 	var authMethod byte
 	if authenticator == nil {
 		authMethod = AuthTypeNotRequired
@@ -63,7 +75,7 @@ func HandleConnection(ctx context.Context, conn net.Conn, authenticator auth.Aut
 		authMethod = AuthTypeUsernamePassword
 	}
 	if !common.Contains(authRequest.Methods, authMethod) {
-		err = WriteAuthResponse(conn, &AuthResponse{
+		err := WriteAuthResponse(conn, &AuthResponse{
 			Version: authRequest.Version,
 			Method:  AuthTypeNoAcceptedMethods,
 		})
@@ -71,7 +83,7 @@ func HandleConnection(ctx context.Context, conn net.Conn, authenticator auth.Aut
 			return E.Cause(err, "write socks auth response")
 		}
 	}
-	err = WriteAuthResponse(conn, &AuthResponse{
+	err := WriteAuthResponse(conn, &AuthResponse{
 		Version: authRequest.Version,
 		Method:  authMethod,
 	})

protocol/socks/protocol.go

@@ -58,6 +58,22 @@ func ReadAuthRequest(reader io.Reader) (*AuthRequest, error) {
 	return request, nil
 }
 
+func ReadAuthRequest0(reader io.Reader) (*AuthRequest, error) {
+	methodLen, err := rw.ReadByte(reader)
+	if err != nil {
+		return nil, E.Cause(err, "read socks auth methods length")
+	}
+	methods, err := rw.ReadBytes(reader, int(methodLen))
+	if err != nil {
+		return nil, E.CauseF(err, "read socks auth methods, length ", methodLen)
+	}
+	request := &AuthRequest{
+		Version5,
+		methods,
+	}
+	return request, nil
+}
+
 //+----+--------+
 //|VER | METHOD |
 //+----+--------+

transport/tcp/handler.go

@@ -6,8 +6,8 @@ import (
 	"net/netip"
 
 	"github.com/sagernet/sing/common"
+	"github.com/sagernet/sing/common/debug"
 	E "github.com/sagernet/sing/common/exceptions"
-	"github.com/sagernet/sing/common/lowmem"
 	M "github.com/sagernet/sing/common/metadata"
 	"github.com/sagernet/sing/common/redir"
 )
@@ -113,7 +113,7 @@ func (l *Listener) loop() {
 			if hErr != nil {
 				l.handler.HandleError(&Error{Conn: tcpConn, Cause: hErr})
 			}
-			lowmem.Free()
+			debug.Free()
 		}()
 	}
 }