diff --git a/common/acme/acme.go b/common/acme/acme.go index 8ce68a8..5117505 100644 --- a/common/acme/acme.go +++ b/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) diff --git a/common/buf/hex.go b/common/buf/hex.go new file mode 100644 index 0000000..ca54f67 --- /dev/null +++ b/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) +} diff --git a/common/lowmem/debug.go b/common/debug/debug.go similarity index 72% rename from common/lowmem/debug.go rename to common/debug/debug.go index 8c1f743..2261d2c 100644 --- a/common/lowmem/debug.go +++ b/common/debug/debug.go @@ -1,5 +1,5 @@ //go:build debug -package lowmem +package debug const Enabled = true diff --git a/common/lowmem/free.go b/common/debug/free.go similarity index 85% rename from common/lowmem/free.go rename to common/debug/free.go index e07ee02..619819f 100644 --- a/common/lowmem/free.go +++ b/common/debug/free.go @@ -1,4 +1,4 @@ -package lowmem +package debug import ( "runtime/debug" diff --git a/common/lowmem/stub.go b/common/debug/stub.go similarity index 73% rename from common/lowmem/stub.go rename to common/debug/stub.go index a2036b9..da3d857 100644 --- a/common/lowmem/stub.go +++ b/common/debug/stub.go @@ -1,5 +1,5 @@ //go:build !debug -package lowmem +package debug const Enabled = false diff --git a/common/log/log.go b/common/log/log.go deleted file mode 100644 index ab986cc..0000000 --- a/common/log/log.go +++ /dev/null @@ -1,7 +0,0 @@ -package log - -import "github.com/sirupsen/logrus" - -func init() { - logrus.StandardLogger().Formatter.(*logrus.TextFormatter).ForceColors = true -} diff --git a/common/log/logrus.go b/common/log/logrus.go new file mode 100644 index 0000000..b8ea66b --- /dev/null +++ b/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 +} diff --git a/common/log/logrus_debug.go b/common/log/logrus_debug.go new file mode 100644 index 0000000..12f80c6 --- /dev/null +++ b/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 + } +} diff --git a/protocol/shadowsocks/shadowaead_2022/protocol.go b/protocol/shadowsocks/shadowaead_2022/protocol.go index a514e42..b78f735 100644 --- a/protocol/shadowsocks/shadowaead_2022/protocol.go +++ b/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())) } diff --git a/protocol/shadowsocks/shadowaead_2022/service.go b/protocol/shadowsocks/shadowaead_2022/service.go index 505bdb6..04bbf90 100644 --- a/protocol/shadowsocks/shadowaead_2022/service.go +++ b/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{ diff --git a/protocol/socks/listener.go b/protocol/socks/listener.go index 40a011d..2fb4fb6 100644 --- a/protocol/socks/listener.go +++ b/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, }) diff --git a/protocol/socks/protocol.go b/protocol/socks/protocol.go index acd163d..e466df3 100644 --- a/protocol/socks/protocol.go +++ b/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 | //+----+--------+ diff --git a/transport/tcp/handler.go b/transport/tcp/handler.go index 9028f66..68b8bbc 100644 --- a/transport/tcp/handler.go +++ b/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() }() } }