From aa04524565256d74479427f765b79ee38cbda881 Mon Sep 17 00:00:00 2001 From: Ledorub Date: Thu, 22 Aug 2024 11:49:05 +0300 Subject: [PATCH] chore: refactor logging (#182) --- cmd/spoof-dpi/main.go | 23 ++++++-------- dns/dns.go | 16 ++++++---- go.mod | 4 ++- go.sum | 17 +++++++++-- proxy/http.go | 25 ++++++++++------ proxy/https.go | 47 +++++++++++++++++------------ proxy/proxy.go | 47 +++++++++++++++++------------ proxy/server.go | 25 +++++++++------- util/context.go | 55 ++++++++++++++++++++++++++++++++++ util/log/log.go | 70 +++++++++++++++++++++++++++++++++++++++++++ 10 files changed, 249 insertions(+), 80 deletions(-) create mode 100644 util/context.go create mode 100644 util/log/log.go diff --git a/cmd/spoof-dpi/main.go b/cmd/spoof-dpi/main.go index 82bb290..340f8c9 100644 --- a/cmd/spoof-dpi/main.go +++ b/cmd/spoof-dpi/main.go @@ -1,12 +1,12 @@ package main import ( + "context" + "github.com/xvzc/SpoofDPI/util/log" "os" "os/signal" "syscall" - "github.com/sirupsen/logrus" - log "github.com/sirupsen/logrus" "github.com/xvzc/SpoofDPI/proxy" "github.com/xvzc/SpoofDPI/util" "github.com/xvzc/SpoofDPI/version" @@ -22,16 +22,11 @@ func main() { config := util.GetConfig() config.Load(args) - pxy := proxy.New(config) - if *config.Debug { - log.SetLevel(log.DebugLevel) - } else { - log.SetLevel(log.InfoLevel) - } + log.InitLogger(config) + ctx := util.GetCtxWithScope(context.Background(), "MAIN") + logger := log.GetCtxLogger(ctx) - log.SetFormatter(&logrus.TextFormatter{ - FullTimestamp: true, - }) + pxy := proxy.New(config) if *config.NoBanner { util.PrintSimpleInfo() @@ -41,11 +36,11 @@ func main() { if *config.SystemProxy { if err := util.SetOsProxy(*config.Port); err != nil { - log.Fatalf("error while changing proxy settings: %s", err) + logger.Fatal().Msgf("error while changing proxy settings: %s", err) } } - go pxy.Start() + go pxy.Start(context.Background()) // Handle signals sigs := make(chan os.Signal, 1) @@ -68,7 +63,7 @@ func main() { if *config.SystemProxy { if err := util.UnsetOsProxy(); err != nil { - log.Fatal(err) + logger.Fatal().Msgf("%s", err) } } } diff --git a/dns/dns.go b/dns/dns.go index a5ea456..1af880c 100644 --- a/dns/dns.go +++ b/dns/dns.go @@ -8,11 +8,13 @@ import ( "time" "github.com/miekg/dns" - log "github.com/sirupsen/logrus" "github.com/xvzc/SpoofDPI/dns/resolver" "github.com/xvzc/SpoofDPI/util" + "github.com/xvzc/SpoofDPI/util/log" ) +const scopeDNS = "DNS" + type Resolver interface { Resolve(ctx context.Context, host string, qTypes []uint16) ([]net.IPAddr, error) String() string @@ -39,16 +41,20 @@ func NewDns(config *util.Config) *Dns { } } -func (d *Dns) ResolveHost(host string, enableDoh bool, useSystemDns bool) (string, error) { +func (d *Dns) ResolveHost(ctx context.Context, host string, enableDoh bool, useSystemDns bool) (string, error) { + ctx = util.GetCtxWithScope(ctx, scopeDNS) + logger := log.GetCtxLogger(ctx) + if ip, err := parseIpAddr(host); err == nil { return ip.String(), nil } clt := d.clientFactory(enableDoh, useSystemDns) - ctx, cancel := context.WithTimeout(context.Background(), 3*time.Second) + ctx, cancel := context.WithTimeout(ctx, 3*time.Second) defer cancel() - log.Debugf("[DNS] resolving %s using %s", host, clt) + logger.Debug().Msgf("resolving %s using %s", host, clt) + t := time.Now() addrs, err := clt.Resolve(ctx, host, []uint16{dns.TypeAAAA, dns.TypeA}) @@ -59,7 +65,7 @@ func (d *Dns) ResolveHost(host string, enableDoh bool, useSystemDns bool) (strin if len(addrs) > 0 { d := time.Since(t).Milliseconds() - log.Debugf("[DNS] resolved %s from %s in %d ms", addrs[0].String(), host, d) + logger.Debug().Msgf("resolved %s from %s in %d ms", addrs[0].String(), host, d) return addrs[0].String(), nil } diff --git a/go.mod b/go.mod index 1b45c00..a1acf28 100644 --- a/go.mod +++ b/go.mod @@ -7,7 +7,7 @@ toolchain go1.21.5 require ( github.com/miekg/dns v1.1.61 github.com/pterm/pterm v0.12.79 - github.com/sirupsen/logrus v1.9.3 + github.com/rs/zerolog v1.33.0 ) require ( @@ -17,6 +17,8 @@ require ( github.com/containerd/console v1.0.3 // indirect github.com/gookit/color v1.5.4 // indirect github.com/lithammer/fuzzysearch v1.1.8 // indirect + github.com/mattn/go-colorable v0.1.13 // indirect + github.com/mattn/go-isatty v0.0.19 // indirect github.com/mattn/go-runewidth v0.0.15 // indirect github.com/rivo/uniseg v0.4.4 // indirect github.com/xo/terminfo v0.0.0-20220910002029-abceb7e1c41e // indirect diff --git a/go.sum b/go.sum index c98a4e4..84049fe 100644 --- a/go.sum +++ b/go.sum @@ -18,9 +18,11 @@ github.com/MarvinJWendt/testza v0.5.2/go.mod h1:xu53QFE5sCdjtMCKk8YMQ2MnymimEctc github.com/atomicgo/cursor v0.0.1/go.mod h1:cBON2QmmrysudxNBFthvMtN32r3jxVRIvzkUiF/RuIk= github.com/containerd/console v1.0.3 h1:lIr7SlA5PxZyMV30bDW0MGbiOPXwc63yRuCP0ARubLw= github.com/containerd/console v1.0.3/go.mod h1:7LqA/THxQ86k76b8c/EMSiaJ3h1eZkMkXar0TQ1gf3U= +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/gookit/color v1.4.2/go.mod h1:fqRyamkC1W8uxl+lxCQxOT09l/vYfZ+QeiX3rKQHCoQ= github.com/gookit/color v1.5.0/go.mod h1:43aQb+Zerm/BWh2GnrgOQm7ffz7tvQXEKV6BFMl7wAo= github.com/gookit/color v1.5.4 h1:FZmqs7XOyGgCAxmWyPslpiok1k05wmY3SJTytgvYFs0= @@ -35,11 +37,17 @@ github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= github.com/lithammer/fuzzysearch v1.1.8 h1:/HIuJnjHuXS8bKaiTMeeDlW2/AyIWk2brx1V8LFgLN4= github.com/lithammer/fuzzysearch v1.1.8/go.mod h1:IdqeyBClc3FFqSzYq/MXESsS4S0FsZ5ajtkr5xPLts4= +github.com/mattn/go-colorable v0.1.13 h1:fFA4WZxdEF4tXPZVKMLwD8oUnCTTo08duU7wxecdEvA= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-runewidth v0.0.13/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w= github.com/mattn/go-runewidth v0.0.15 h1:UNAjwbU9l54TA3KzvqLGxwWjHmMgBUVhBiTjelZgg3U= github.com/mattn/go-runewidth v0.0.15/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w= github.com/miekg/dns v1.1.61 h1:nLxbwF3XxhwVSm8g9Dghm9MHPaUZuqhPiGL+675ZmEs= github.com/miekg/dns v1.1.61/go.mod h1:mnAarhS3nWaW+NVP2wTkYVIZyHNJ098SJZUki3eykwQ= +github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/pterm/pterm v0.12.27/go.mod h1:PhQ89w4i95rhgE+xedAoqous6K9X+r6aSOI2eFF7DZI= @@ -54,10 +62,11 @@ github.com/pterm/pterm v0.12.79/go.mod h1:1v/gzOF1N0FsjbgTHZ1wVycRkKiatFvJSJC4IG github.com/rivo/uniseg v0.2.0/go.mod h1:J6wj4VEh+S6ZtnVlnTBMWIodfgj8LQOQFoIToxlJtxc= github.com/rivo/uniseg v0.4.4 h1:8TfxU8dW6PdqD27gjM8MVNuicgxIjxpm4K7x4jp8sis= github.com/rivo/uniseg v0.4.4/go.mod h1:FN3SvrM+Zdj16jyLfmOkMNblXMcoc8DfTHruCPUcx88= +github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg= +github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8= +github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss= github.com/sergi/go-diff v1.2.0 h1:XU+rvMAioB0UC3q1MFrIQy4Vo5/4VsRDQQXHsEya6xQ= github.com/sergi/go-diff v1.2.0/go.mod h1:STckp+ISIX8hZLjrqAeVduY0gWCT9IjLuqbuNXdaHfM= -github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ= -github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/stretchr/testify v1.6.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= @@ -95,9 +104,11 @@ golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBc golang.org/x/sys v0.0.0-20211013075003-97ac67df715c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220319134239-a9b59b0215f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.0.0-20220722155257-8c9f86f7a55f/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.22.0 h1:RI27ohtqKCnwULzJLqkv897zojh5/DwS/ENaMzUOaWI= golang.org/x/sys v0.22.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= diff --git a/proxy/http.go b/proxy/http.go index 962a40f..1a7a5fa 100644 --- a/proxy/http.go +++ b/proxy/http.go @@ -1,15 +1,22 @@ package proxy import ( + "context" + "github.com/xvzc/SpoofDPI/util" "net" "strconv" - log "github.com/sirupsen/logrus" + "github.com/xvzc/SpoofDPI/util/log" "github.com/xvzc/SpoofDPI/packet" ) -func (pxy *Proxy) handleHttp(lConn *net.TCPConn, pkt *packet.HttpRequest, ip string) { +const protoHTTP = "HTTP" + +func (pxy *Proxy) handleHttp(ctx context.Context, lConn *net.TCPConn, pkt *packet.HttpRequest, ip string) { + ctx = util.GetCtxWithScope(ctx, protoHTTP) + logger := log.GetCtxLogger(ctx) + pkt.Tidy() // Create a connection to the requested server @@ -18,28 +25,28 @@ func (pxy *Proxy) handleHttp(lConn *net.TCPConn, pkt *packet.HttpRequest, ip str if pkt.Port() != "" { port, err = strconv.Atoi(pkt.Port()) if err != nil { - log.Debugf("[HTTP] error while parsing port for %s aborting..", pkt.Domain()) + logger.Debug().Msgf("error while parsing port for %s aborting..", pkt.Domain()) } } rConn, err := net.DialTCP("tcp", nil, &net.TCPAddr{IP: net.ParseIP(ip), Port: port}) if err != nil { lConn.Close() - log.Debug("[HTTP] ", err) + logger.Debug().Msgf("%s", err) return } - log.Debugf("[HTTP] new connection to the server %s -> %s", rConn.LocalAddr(), pkt.Domain()) + logger.Debug().Msgf("new connection to the server %s -> %s", rConn.LocalAddr(), pkt.Domain()) - go Serve(rConn, lConn, "[HTTP]", pkt.Domain(), lConn.RemoteAddr().String(), pxy.timeout) + go Serve(ctx, rConn, lConn, protoHTTP, pkt.Domain(), lConn.RemoteAddr().String(), pxy.timeout) _, err = rConn.Write(pkt.Raw()) if err != nil { - log.Debugf("[HTTP] error sending request to %s: %s", pkt.Domain(), err) + logger.Debug().Msgf("error sending request to %s: %s", pkt.Domain(), err) return } - log.Debugf("[HTTP] sent a request to %s", pkt.Domain()) + logger.Debug().Msgf("sent a request to %s", pkt.Domain()) - go Serve(lConn, rConn, "[HTTP]", lConn.RemoteAddr().String(), pkt.Domain(), pxy.timeout) + go Serve(ctx, lConn, rConn, protoHTTP, lConn.RemoteAddr().String(), pkt.Domain(), pxy.timeout) } diff --git a/proxy/https.go b/proxy/https.go index 8c76651..86ab80c 100644 --- a/proxy/https.go +++ b/proxy/https.go @@ -1,77 +1,86 @@ package proxy import ( + "context" + "github.com/xvzc/SpoofDPI/util" "net" "strconv" - log "github.com/sirupsen/logrus" "github.com/xvzc/SpoofDPI/packet" + "github.com/xvzc/SpoofDPI/util/log" ) -func (pxy *Proxy) handleHttps(lConn *net.TCPConn, exploit bool, initPkt *packet.HttpRequest, ip string) { +const protoHTTPS = "HTTPS" + +func (pxy *Proxy) handleHttps(ctx context.Context, lConn *net.TCPConn, exploit bool, initPkt *packet.HttpRequest, ip string) { + ctx = util.GetCtxWithScope(ctx, protoHTTPS) + logger := log.GetCtxLogger(ctx) + // Create a connection to the requested server var port int = 443 var err error if initPkt.Port() != "" { port, err = strconv.Atoi(initPkt.Port()) if err != nil { - log.Debugf("[HTTPS] error parsing port for %s aborting..", initPkt.Domain()) + logger.Debug().Msgf("error parsing port for %s aborting..", initPkt.Domain()) } } rConn, err := net.DialTCP("tcp", nil, &net.TCPAddr{IP: net.ParseIP(ip), Port: port}) if err != nil { lConn.Close() - log.Debug("[HTTPS] ", err) + logger.Debug().Msgf("%s", err) return } - log.Debugf("[HTTPS] new connection to the server %s -> %s", rConn.LocalAddr(), initPkt.Domain()) + logger.Debug().Msgf("new connection to the server %s -> %s", rConn.LocalAddr(), initPkt.Domain()) _, err = lConn.Write([]byte(initPkt.Version() + " 200 Connection Established\r\n\r\n")) if err != nil { - log.Debugf("[HTTPS] error sending 200 connection established to the client: %s", err) + logger.Debug().Msgf("error sending 200 connection established to the client: %s", err) return } - log.Debugf("[HTTPS] sent connection estabalished to %s", lConn.RemoteAddr()) + logger.Debug().Msgf("sent connection estabalished to %s", lConn.RemoteAddr()) // Read client hello m, err := packet.ReadTLSMessage(lConn) if err != nil || !m.IsClientHello() { - log.Debugf("[HTTPS] error reading client hello from %s: %s", lConn.RemoteAddr().String(), err) + logger.Debug().Msgf("error reading client hello from %s: %s", lConn.RemoteAddr().String(), err) return } clientHello := m.Raw - log.Debugf("[HTTPS] client sent hello %d bytes", len(clientHello)) + logger.Debug().Msgf("client sent hello %d bytes", len(clientHello)) // Generate a go routine that reads from the server - go Serve(rConn, lConn, "[HTTPS]", initPkt.Domain(), lConn.RemoteAddr().String(), pxy.timeout) + go Serve(ctx, rConn, lConn, protoHTTPS, initPkt.Domain(), lConn.RemoteAddr().String(), pxy.timeout) if exploit { - log.Debugf("[HTTPS] writing chunked client hello to %s", initPkt.Domain()) - chunks := splitInChunks(clientHello, pxy.windowSize) + logger.Debug().Msgf("writing chunked client hello to %s", initPkt.Domain()) + chunks := splitInChunks(ctx, clientHello, pxy.windowSize) if _, err := writeChunks(rConn, chunks); err != nil { - log.Debugf("[HTTPS] error writing chunked client hello to %s: %s", initPkt.Domain(), err) + logger.Debug().Msgf("error writing chunked client hello to %s: %s", initPkt.Domain(), err) return } } else { - log.Debugf("[HTTPS] writing plain client hello to %s", initPkt.Domain()) + logger.Debug().Msgf("writing plain client hello to %s", initPkt.Domain()) if _, err := rConn.Write(clientHello); err != nil { - log.Debugf("[HTTPS] error writing plain client hello to %s: %s", initPkt.Domain(), err) + logger.Debug().Msgf("error writing plain client hello to %s: %s", initPkt.Domain(), err) return } } - go Serve(lConn, rConn, "[HTTPS]", lConn.RemoteAddr().String(), initPkt.Domain(), pxy.timeout) + go Serve(ctx, lConn, rConn, protoHTTPS, lConn.RemoteAddr().String(), initPkt.Domain(), pxy.timeout) } -func splitInChunks(bytes []byte, size int) [][]byte { +func splitInChunks(ctx context.Context, bytes []byte, size int) [][]byte { + logger := log.GetCtxLogger(ctx) + var chunks [][]byte var raw []byte = bytes - log.Debugf("[HTTPS] window-size: %d", size) + logger.Debug().Msgf("window-size: %d", size) if size > 0 { for { @@ -98,7 +107,7 @@ func splitInChunks(bytes []byte, size int) [][]byte { return [][]byte{raw} } - log.Debug("[HTTPS] using legacy fragmentation") + logger.Debug().Msg("using legacy fragmentation") return [][]byte{raw[:1], raw[1:]} } diff --git a/proxy/proxy.go b/proxy/proxy.go index 180b975..a2775dd 100644 --- a/proxy/proxy.go +++ b/proxy/proxy.go @@ -1,18 +1,20 @@ package proxy import ( - "fmt" + "context" "net" "os" "regexp" "strconv" - log "github.com/sirupsen/logrus" "github.com/xvzc/SpoofDPI/dns" "github.com/xvzc/SpoofDPI/packet" "github.com/xvzc/SpoofDPI/util" + "github.com/xvzc/SpoofDPI/util/log" ) +const scopeProxy = "PROXY" + type Proxy struct { addr string port int @@ -35,41 +37,46 @@ func New(config *util.Config) *Proxy { } } -func (pxy *Proxy) Start() { +func (pxy *Proxy) Start(ctx context.Context) { + ctx = util.GetCtxWithScope(ctx, scopeProxy) + logger := log.GetCtxLogger(ctx) + l, err := net.ListenTCP("tcp", &net.TCPAddr{IP: net.ParseIP(pxy.addr), Port: pxy.port}) if err != nil { - log.Fatal("[PROXY] error creating listener: ", err) + logger.Fatal().Msgf("error creating listener: %s", err) os.Exit(1) } if pxy.timeout > 0 { - log.Println(fmt.Sprintf("[PROXY] connection timeout is set to %dms", pxy.timeout)) + logger.Debug().Msgf("connection timeout is set to %d ms", pxy.timeout) } - log.Println("[PROXY] created a listener on port", pxy.port) + logger.Info().Msgf("created a listener on port %d", pxy.port) if len(pxy.allowedPattern) > 0 { - log.Println("[PROXY] number of white-listed pattern:", len(pxy.allowedPattern)) + logger.Debug().Msgf("number of white-listed pattern: %d", len(pxy.allowedPattern)) } for { conn, err := l.Accept() if err != nil { - log.Fatal("[PROXY] error accepting connection: ", err) + logger.Fatal().Msgf("error accepting connection: %s", err) continue } go func() { + ctx := util.GetCtxWithTraceId(ctx) + pkt, err := packet.ReadHttpRequest(conn) if err != nil { - log.Debug("[PROXY] error while parsing request: ", err) + logger.Debug().Msgf("error while parsing request: %s", err) conn.Close() return } - log.Debug("[PROXY] request from ", conn.RemoteAddr(), "\n\n", string(pkt.Raw())) + logger.Debug().Msgf("request from %s\n\n%s", conn.RemoteAddr(), pkt.Raw()) if !pkt.IsValidMethod() { - log.Debug("[PROXY] unsupported method: ", pkt.Method()) + logger.Debug().Msgf("unsupported method: %s", pkt.Method()) conn.Close() return } @@ -77,25 +84,25 @@ func (pxy *Proxy) Start() { matched := pxy.patternMatches([]byte(pkt.Domain())) useSystemDns := !matched - ip, err := pxy.resolver.ResolveHost(pkt.Domain(), pxy.enableDoh, useSystemDns) + ip, err := pxy.resolver.ResolveHost(ctx, pkt.Domain(), pxy.enableDoh, useSystemDns) if err != nil { - log.Debug("[PROXY] error while dns lookup: ", pkt.Domain(), " ", err) + logger.Debug().Msgf("error while dns lookup: %s %s", pkt.Domain(), err) conn.Write([]byte(pkt.Version() + " 502 Bad Gateway\r\n\r\n")) conn.Close() return } // Avoid recursively querying self - if pkt.Port() == strconv.Itoa(pxy.port) && isLoopedRequest(net.ParseIP(ip)) { - log.Error("[PROXY] looped request has been detected. aborting.") + if pkt.Port() == strconv.Itoa(pxy.port) && isLoopedRequest(ctx, net.ParseIP(ip)) { + logger.Error().Msg("looped request has been detected. aborting.") conn.Close() return } if pkt.IsConnectMethod() { - pxy.handleHttps(conn.(*net.TCPConn), matched, pkt, ip) + pxy.handleHttps(ctx, conn.(*net.TCPConn), matched, pkt, ip) } else { - pxy.handleHttp(conn.(*net.TCPConn), pkt, ip) + pxy.handleHttp(ctx, conn.(*net.TCPConn), pkt, ip) } }() } @@ -115,16 +122,18 @@ func (pxy *Proxy) patternMatches(bytes []byte) bool { return false } -func isLoopedRequest(ip net.IP) bool { +func isLoopedRequest(ctx context.Context, ip net.IP) bool { if ip.IsLoopback() { return true } + logger := log.GetCtxLogger(ctx) + // Get list of available addresses // See `ip -4 addr show` addr, err := net.InterfaceAddrs() // needs AF_NETLINK on linux if err != nil { - log.Error("[PROXY] error while getting addresses of our network interfaces: ", err) + logger.Error().Msgf("error while getting addresses of our network interfaces: %s", err) return false } diff --git a/proxy/server.go b/proxy/server.go index 0c3bb09..e74cb13 100644 --- a/proxy/server.go +++ b/proxy/server.go @@ -1,12 +1,14 @@ package proxy import ( + "context" "errors" + "github.com/xvzc/SpoofDPI/util" "io" "net" "time" - log "github.com/sirupsen/logrus" + "github.com/xvzc/SpoofDPI/util/log" ) const ( @@ -14,12 +16,12 @@ const ( TLSHeaderLen = 5 ) -func ReadBytes(conn *net.TCPConn, dest []byte) ([]byte, error) { - n, err := readBytesInternal(conn, dest) +func ReadBytes(ctx context.Context, conn *net.TCPConn, dest []byte) ([]byte, error) { + n, err := readBytesInternal(ctx, conn, dest) return dest[:n], err } -func readBytesInternal(conn *net.TCPConn, dest []byte) (int, error) { +func readBytesInternal(ctx context.Context, conn *net.TCPConn, dest []byte) (int, error) { totalRead, err := conn.Read(dest) if err != nil { var opError *net.OpError @@ -33,12 +35,15 @@ func readBytesInternal(conn *net.TCPConn, dest []byte) (int, error) { return totalRead, nil } -func Serve(from *net.TCPConn, to *net.TCPConn, proto string, fd string, td string, timeout int) { +func Serve(ctx context.Context, from *net.TCPConn, to *net.TCPConn, proto string, fd string, td string, timeout int) { + ctx = util.GetCtxWithScope(ctx, proto) + logger := log.GetCtxLogger(ctx) + defer func() { from.Close() to.Close() - log.Debugf("%s closing proxy connection: %s -> %s", proto, fd, td) + logger.Debug().Msgf("closing proxy connection: %s -> %s", fd, td) }() buf := make([]byte, BufferSize) @@ -49,18 +54,18 @@ func Serve(from *net.TCPConn, to *net.TCPConn, proto string, fd string, td strin ) } - bytesRead, err := ReadBytes(from, buf) + bytesRead, err := ReadBytes(ctx, from, buf) if err != nil { if err == io.EOF { - log.Debugf("%s finished reading from %s", proto, fd) + logger.Debug().Msgf("finished reading from %s", fd) return } - log.Debugf("%s error reading from %s: %s", proto, fd, err) + logger.Debug().Msgf("error reading from %s: %s", fd, err) return } if _, err := to.Write(bytesRead); err != nil { - log.Debugf("%s error Writing to %s", proto, td) + logger.Debug().Msgf("error Writing to %s", td) return } } diff --git a/util/context.go b/util/context.go new file mode 100644 index 0000000..d557a02 --- /dev/null +++ b/util/context.go @@ -0,0 +1,55 @@ +package util + +import ( + "context" + "math/rand" + "strings" +) + +type scopeCtxKey struct{} + +func GetCtxWithScope(ctx context.Context, scope string) context.Context { + return context.WithValue(ctx, scopeCtxKey{}, scope) +} + +func GetScopeFromCtx(ctx context.Context) (string, bool) { + if scope, ok := ctx.Value(scopeCtxKey{}).(string); ok { + return scope, true + } + return "", false +} + +type traceIdCtxKey struct{} + +func GetCtxWithTraceId(ctx context.Context) context.Context { + return context.WithValue(ctx, traceIdCtxKey{}, generateTraceId()) +} + +func GetTraceIdFromCtx(ctx context.Context) (string, bool) { + if traceId, ok := ctx.Value(traceIdCtxKey{}).(string); ok { + return traceId, true + } + return "", false +} + +func generateTraceId() string { + sb := strings.Builder{} + sb.Grow(22) + + var q uint64 + var r uint8 + for i := 0; i < 32; i++ { + if i%15 == 0 { + q = rand.Uint64() + } + q, r = q>>4, uint8(q&0xF) + if r > 9 { + r += 0x27 + } + sb.WriteByte(r + 0x30) + if i&3 == 3 && i != 31 { + sb.WriteByte(0x2D) + } + } + return sb.String() +} diff --git a/util/log/log.go b/util/log/log.go new file mode 100644 index 0000000..7b580bc --- /dev/null +++ b/util/log/log.go @@ -0,0 +1,70 @@ +package log + +import ( + "context" + "fmt" + "github.com/rs/zerolog" + "github.com/xvzc/SpoofDPI/util" + "os" + "time" +) + +const ( + scopeFieldName = "scope" + traceIdFieldName = "trace_id" +) + +var logger zerolog.Logger + +func GetCtxLogger(ctx context.Context) zerolog.Logger { + return logger.With().Ctx(ctx).Logger() +} + +func InitLogger(cfg *util.Config) { + partsOrder := []string{ + zerolog.TimestampFieldName, + zerolog.LevelFieldName, + traceIdFieldName, + scopeFieldName, + zerolog.MessageFieldName, + } + + consoleWriter := zerolog.ConsoleWriter{ + Out: os.Stdout, + TimeFormat: time.RFC3339, + PartsOrder: partsOrder, + FormatPrepare: func(m map[string]any) error { + formatFieldValue[string](m, "%s", traceIdFieldName) + formatFieldValue[string](m, "[%s]", scopeFieldName) + return nil + }, + FieldsExclude: []string{traceIdFieldName, scopeFieldName}, + } + + logger = zerolog.New(consoleWriter).Hook(ctxHook{}) + if *cfg.Debug { + logger = logger.Level(zerolog.DebugLevel) + } else { + logger = logger.Level(zerolog.InfoLevel) + } + logger = logger.With().Timestamp().Logger() +} + +func formatFieldValue[T any](vs map[string]any, format string, field string) { + if v, ok := vs[field].(T); ok { + vs[field] = fmt.Sprintf(format, v) + } else { + vs[field] = "" + } +} + +type ctxHook struct{} + +func (h ctxHook) Run(e *zerolog.Event, level zerolog.Level, msg string) { + if scope, ok := util.GetScopeFromCtx(e.GetCtx()); ok { + e.Str(scopeFieldName, scope) + } + if traceId, ok := util.GetTraceIdFromCtx(e.GetCtx()); ok { + e.Str(traceIdFieldName, traceId) + } +}