revamp debug logging (#57)

* revamp debug logging

* cidr acl minor fix

* empty ACL means accept

acl/acl.go

@@ -10,36 +10,19 @@ import (
 )
 
 // Decision is the type of decision that an ACL can make for each connection info
-type Decision uint8
-
-func (d Decision) String() string {
-	switch d {
-	case Accept:
-		return "Accept"
-	case Reject:
-		return "Reject"
-	case ProxyIP:
-		return "ProxyIP"
-	case OriginIP:
-		return "OriginIP"
-	case Override:
-		return "Override"
-	default:
-		return "Unknown"
-	}
-}
+type Decision string
 
 const (
 	// Accept shows the indifference of the ACL to the connection
-	Accept Decision = iota
+	Accept Decision = "Accept"
 	// Reject shows that the ACL has rejected the connection. each ACL should check this before proceeding to check the connection against its rules
-	Reject
+	Reject Decision = "Reject"
 	// ProxyIP shows that the ACL has decided to proxy the connection through sniproxy rather than the origin IP
-	ProxyIP
+	ProxyIP Decision = "ProxyIP"
 	// OriginIP shows that the ACL has decided to proxy the connection through the origin IP rather than sniproxy
-	OriginIP
+	OriginIP Decision = "OriginIP"
 	// Override shows that the ACL has decided to override the connection and proxy it through the specified DstIP and DstPort
-	Override
+	Override Decision = "Override"
 )
 
 // ConnInfo contains all the information about a connection that is available
@@ -97,6 +80,10 @@ func MakeDecision(c *ConnInfo, a []ACL) error {
 			return err
 		}
 	}
+	// if ACL list is empty, we accept the connection
+	if len(a) == 0 {
+		c.Decision = Accept
+	}
 	return nil
 }
 

acl/cidr.go

@@ -103,11 +103,16 @@ func (d *cidr) loadCIDRCSVWorker() {
 
 // Decide checks if the connection is allowed or rejected
 func (d cidr) Decide(c *ConnInfo) error {
+	d.logger.Debug().Any("conn", c).Msg("deciding on cidr acl")
 	// get the IP from the connection
 	ipPort := strings.Split(c.SrcIP.String(), ":")
 	ip := net.ParseIP(ipPort[0])
 
 	prevDec := c.Decision
+	// set the prev decision to accept if it's empty
+	if prevDec == "" {
+		prevDec = Accept
+	}
 
 	if match, err := d.RejectRanger.Contains(ip); match && err == nil {
 		c.Decision = Reject

acl/domain.go

@@ -139,9 +139,11 @@ func (d *domain) LoadDomainsCSVWorker() {
 
 // implement domain as an ACL interface
 func (d domain) Decide(c *ConnInfo) error {
+	d.logger.Debug().Any("conn", c).Msg("deciding on domain acl")
 
 	if c.Decision == Reject {
 		c.DstIP = net.TCPAddr{IP: net.IPv4zero, Port: 0}
+		d.logger.Debug().Any("conn", c).Msg("decided on domain acl")
 		return nil
 	}
 	if d.inDomainList(c.Domain) {
@@ -151,6 +153,7 @@ func (d domain) Decide(c *ConnInfo) error {
 		d.logger.Debug().Msgf("domain going through proxy: %s", c.Domain)
 		c.Decision = ProxyIP
 	}
+	d.logger.Debug().Any("conn", c).Msg("decided on domain acl")
 	return nil
 }
 func (d domain) Name() string {

acl/geoip.go

@@ -145,12 +145,13 @@ func (g geoIP) checkGeoIPSkip(addr net.Addr) bool {
 
 // implement the ACL interface
 func (g geoIP) Decide(c *ConnInfo) error {
+	g.logger.Debug().Any("conn", c).Msg("deciding on geoip acl")
 	// in checkGeoIPSkip, false is reject
 	if !g.checkGeoIPSkip(c.SrcIP) {
 		g.logger.Info().Msgf("rejecting connection from ip %s", c.SrcIP)
 		c.Decision = Reject
 	}
-	g.logger.Debug().Msgf("GeoIP decision for ip %s is %#v", c.SrcIP, c.Decision)
+	g.logger.Debug().Any("conn", c).Msg("decided on geoip acl")
 	return nil
 }
 func (g geoIP) Name() string {

acl/override.go

@@ -61,15 +61,17 @@ func (o *override) startProxy() {
 }
 
 func (o override) Decide(c *ConnInfo) error {
+	o.logger.Debug().Any("conn", c).Msg("deciding on override acl")
 	domain := strings.TrimSuffix(c.Domain, ".")
 	for k := range o.rules {
 		if strings.TrimSuffix(k, ".") == domain {
 			c.Decision = Override
 			a, _ := net.ResolveTCPAddr("tcp", fmt.Sprintf("127.0.0.1:%d", o.tcpproxyport))
 			c.DstIP = *a
-			return nil
+			break
 		}
 	}
+	o.logger.Debug().Any("conn", c).Msg("decided on override acl")
 	return nil
 }
 

dns.go

@@ -58,7 +58,7 @@ func processQuestion(q dns.Question, decision acl.Decision) ([]dns.RR, error) {
 	switch decision {
 
 	// Return the public IP.
-	case acl.ProxyIP, acl.Override:
+	case acl.ProxyIP, acl.Override, acl.Accept: // TODO: accept should be here?
 		c.proxiedDNS.Inc(1)
 		dnslog.Info().Msgf("returned sniproxy address for domain %s", q.Name)
 
@@ -210,7 +210,7 @@ func runDNS(l zerolog.Logger) {
 			Cert:       crt,
 			Upstream:   c.BindDNSOverUDP,
 			TLSCompat:  true,
-			Debug:      httpslog.GetLevel() == zerolog.DebugLevel,
+			Debug:      dnslog.GetLevel() == zerolog.DebugLevel,
 		}
 		doqServer, err := doqserver.New(doqConf)
 		if err != nil {

go.mod

@@ -18,7 +18,7 @@ require (
 	github.com/spf13/cobra v1.7.0
 	github.com/txthinking/socks5 v0.0.0-20230325130024-4230056ae301
 	github.com/yl2chen/cidranger v1.0.2
-	golang.org/x/exp v0.0.0-20230510235704-dd950f8aeaea
+	golang.org/x/exp v0.0.0-20230522175609-2e198f4a06a1
 	golang.org/x/net v0.10.0
 	inet.af/tcpproxy v0.0.0-20221017015627-91f861402626
 )
@@ -35,16 +35,16 @@ require (
 	github.com/inconshreveable/mousetrap v1.1.0 // indirect
 	github.com/infobloxopen/go-trees v0.0.0-20221216143356-66ceba885ebc // indirect
 	github.com/mattn/go-colorable v0.1.13 // indirect
-	github.com/mattn/go-isatty v0.0.18 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
 	github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect
 	github.com/mitchellh/copystructure v1.2.0 // indirect
 	github.com/mitchellh/mapstructure v1.5.0 // indirect
 	github.com/mitchellh/reflectwalk v1.0.2 // indirect
-	github.com/onsi/ginkgo/v2 v2.9.4 // indirect
+	github.com/onsi/ginkgo/v2 v2.9.5 // indirect
 	github.com/patrickmn/go-cache v2.1.0+incompatible // indirect
 	github.com/prometheus/client_model v0.4.0 // indirect
-	github.com/prometheus/common v0.43.0 // indirect
-	github.com/prometheus/procfs v0.9.0 // indirect
+	github.com/prometheus/common v0.44.0 // indirect
+	github.com/prometheus/procfs v0.10.1 // indirect
 	github.com/quic-go/qtls-go1-19 v0.3.2 // indirect
 	github.com/quic-go/qtls-go1-20 v0.2.2 // indirect
 	github.com/quic-go/quic-go v0.34.0 // indirect

go.sum

@@ -195,8 +195,8 @@ github.com/mattn/go-isatty v0.0.11/go.mod h1:PhnuNfih5lzO57/f3n+odYbM4JtupLOxQOA
 github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
 github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM=
-github.com/mattn/go-isatty v0.0.18 h1:DOKFKCQ7FNG2L1rbrmstDN4QVRdS89Nkh85u68Uwp98=
-github.com/mattn/go-isatty v0.0.18/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
+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/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
 github.com/matttproud/golang_protobuf_extensions v1.0.4 h1:mmDVorXM7PCGKw94cs5zkfA9PSy5pEvNWRP0ET0TIVo=
 github.com/matttproud/golang_protobuf_extensions v1.0.4/go.mod h1:BSXmuO+STAnVfrANrmjBb36TMTDstsz7MSK+HVaYKv4=
@@ -233,8 +233,8 @@ github.com/mwitkow/go-conntrack v0.0.0-20161129095857-cc309e4a2223/go.mod h1:qRW
 github.com/mwitkow/go-conntrack v0.0.0-20190716064945-2f068394615f/go.mod h1:qRWi+5nqEBWmkhHvq77mSJWrCKwh8bxhgT7d/eI7P4U=
 github.com/npillmayer/nestext v0.1.3/go.mod h1:h2lrijH8jpicr25dFY+oAJLyzlya6jhnuG+zWp9L0Uk=
 github.com/oklog/run v1.0.0/go.mod h1:dlhp/R75TPv97u0XWUtDeV/lRKWPKSdTuV0TZvrmrQA=
-github.com/onsi/ginkgo/v2 v2.9.4 h1:xR7vG4IXt5RWx6FfIjyAtsoMAtnc3C/rFXBBd2AjZwE=
-github.com/onsi/ginkgo/v2 v2.9.4/go.mod h1:gCQYp2Q+kSoIj7ykSVb9nskRSsR6PUj4AiLywzIhbKM=
+github.com/onsi/ginkgo/v2 v2.9.5 h1:+6Hr4uxzP4XIUyAkg61dWBw8lb/gc4/X5luuxN/EC+Q=
+github.com/onsi/ginkgo/v2 v2.9.5/go.mod h1:tvAoo1QUJwNEU2ITftXTpR7R1RbCzoZUOs3RonqW57k=
 github.com/onsi/gomega v1.27.6 h1:ENqfyGeS5AX/rlXDd/ETokDz93u0YufY1Pgxuy/PvWE=
 github.com/oschwald/maxminddb-golang v1.10.0 h1:Xp1u0ZhqkSuopaKmk1WwHtjF0H9Hd9181uj2MQ5Vndg=
 github.com/oschwald/maxminddb-golang v1.10.0/go.mod h1:Y2ELenReaLAZ0b400URyGwvYxHV1dLIxBuyOsyYjHK0=
@@ -269,15 +269,15 @@ github.com/prometheus/common v0.4.1/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y8
 github.com/prometheus/common v0.6.0/go.mod h1:eBmuwkDJBwy6iBfxCBob6t6dR6ENT/y+J+Zk0j9GMYc=
 github.com/prometheus/common v0.10.0/go.mod h1:Tlit/dnDKsSWFlCLTWaA1cyBgKHSMdTB80sz/V91rCo=
 github.com/prometheus/common v0.26.0/go.mod h1:M7rCNAaPfAosfx8veZJCuw84e35h3Cfd9VFqTh1DIvc=
-github.com/prometheus/common v0.43.0 h1:iq+BVjvYLei5f27wiuNiB1DN6DYQkp1c8Bx0Vykh5us=
-github.com/prometheus/common v0.43.0/go.mod h1:NCvr5cQIh3Y/gy73/RdVtC9r8xxrxwJnB+2lB3BxrFc=
+github.com/prometheus/common v0.44.0 h1:+5BrQJwiBB9xsMygAB3TNvpQKOwlkc25LbISbrdOOfY=
+github.com/prometheus/common v0.44.0/go.mod h1:ofAIvZbQ1e/nugmZGz4/qCb9Ap1VoSTIO7x0VV9VvuY=
 github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
 github.com/prometheus/procfs v0.0.2/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA=
 github.com/prometheus/procfs v0.0.3/go.mod h1:4A/X28fw3Fc593LaREMrKMqOKvUAntwMDaekg4FpcdQ=
 github.com/prometheus/procfs v0.1.3/go.mod h1:lV6e/gmhEcM9IjHGsFOCxxuZ+z1YqCvr4OA4YeYWdaU=
 github.com/prometheus/procfs v0.6.0/go.mod h1:cz+aTbrPOrUb4q7XlbU9ygM+/jj0fzG6c1xBZuNvfVA=
-github.com/prometheus/procfs v0.9.0 h1:wzCHvIvM5SxWqYvwgVL7yJY8Lz3PKn49KQtpgMYJfhI=
-github.com/prometheus/procfs v0.9.0/go.mod h1:+pB4zwohETzFnmlpe6yd2lSc+0/46IYZRB/chUwxUZY=
+github.com/prometheus/procfs v0.10.1 h1:kYK1Va/YMlutzCGazswoHKo//tZVlFpKYh+PymziUAg=
+github.com/prometheus/procfs v0.10.1/go.mod h1:nwNm2aOCAYw8uTR/9bWRREkZFxAUcWzPHWJq+XBB/FM=
 github.com/quic-go/qtls-go1-19 v0.3.2 h1:tFxjCFcTQzK+oMxG6Zcvp4Dq8dx4yD3dDiIiyc86Z5U=
 github.com/quic-go/qtls-go1-19 v0.3.2/go.mod h1:ySOI96ew8lnoKPtSqx2BlI5wCpUVPT05RMAlajtnyOI=
 github.com/quic-go/qtls-go1-20 v0.2.2 h1:WLOPx6OY/hxtTxKV1Zrq20FtXtDEkeY00CGQm8GEa3E=
@@ -345,8 +345,8 @@ golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5y
 golang.org/x/crypto v0.9.0 h1:LF6fAI+IutBocDJ2OT0Q1g8plpYljMZ4+lty+dsqw3g=
 golang.org/x/crypto v0.9.0/go.mod h1:yrmDGqONDYtNj3tH8X9dzUun2m2lzPa9ngI6/RUPGR0=
 golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA=
-golang.org/x/exp v0.0.0-20230510235704-dd950f8aeaea h1:vLCWI/yYrdEHyN2JzIzPO3aaQJHQdp89IZBA/+azVC4=
-golang.org/x/exp v0.0.0-20230510235704-dd950f8aeaea/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w=
+golang.org/x/exp v0.0.0-20230522175609-2e198f4a06a1 h1:k/i9J1pBpvlfR+9QsetwPyERsqu1GIbi967PQMq3Ivc=
+golang.org/x/exp v0.0.0-20230522175609-2e198f4a06a1/go.mod h1:V1LtkGg67GoY2N1AnLN78QLrzxkLyJw7RJb1gzOOz9w=
 golang.org/x/lint v0.0.0-20181026193005-c67002cb31c3/go.mod h1:UVdnD1Gm6xHRNCYTkRU2/jEulfH38KcIWyp/GAMgvoE=
 golang.org/x/lint v0.0.0-20190227174305-5b3e6a55c961/go.mod h1:wehouNa3lNwaWXcvxsM5YxQ5yQlVC4a0KAMCusXpPoU=
 golang.org/x/lint v0.0.0-20190313153728-d0100b6bd8b3/go.mod h1:6SW0HCj/g11FgYtHlgUYUwCkIfeOF89ocIRzGO/8vkc=

httpproxy.go

@@ -11,7 +11,8 @@ import (
 	"github.com/rs/zerolog"
 )
 
-var httplog = logger.With().Str("service", "http").Logger()
+// var httplog = logger.With().Str("service", "http").Logger()
+var httplog zerolog.Logger
 
 var passthruRequestHeaderKeys = [...]string{
 	"Accept",
@@ -67,8 +68,8 @@ func handle80(w http.ResponseWriter, r *http.Request) {
 		Domain: r.Host,
 	}
 	acl.MakeDecision(&connInfo, c.acl)
-	if connInfo.Decision == acl.Reject || connInfo.Decision == acl.ProxyIP || err != nil {
-		httplog.Info().Msgf("rejected request from ip: %s", r.RemoteAddr)
+	if connInfo.Decision == acl.Reject || connInfo.Decision == acl.OriginIP || err != nil {
+		httplog.Info().Str("src_ip", r.RemoteAddr).Msgf("rejected request")
 		http.Error(w, "Could not reach origin server", 403)
 		return
 	}
@@ -79,7 +80,7 @@ func handle80(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	httplog.Info().Msgf("REQ method %s, host: %s, url: %s", r.Method, r.Host, r.URL)
+	httplog.Info().Str("method", r.Method).Str("host", r.Host).Str("url", r.URL.String()).Msg("request received")
 
 	// Construct filtered header to send to origin server
 	hh := http.Header{}

https.go

@@ -9,9 +9,7 @@ import (
 	"golang.org/x/net/proxy"
 )
 
-var httpslog = logger.With().Str("service", "https").Logger()
-
-func handle443(conn net.Conn) error {
+func handle443(conn net.Conn, httpslog zerolog.Logger) error {
 	c.recievedHTTPS.Inc(1)
 
 	defer conn.Close()
@@ -33,20 +31,20 @@ func handle443(conn net.Conn) error {
 	acl.MakeDecision(&connInfo, c.acl)
 
 	if connInfo.Decision == acl.Reject {
-		httpslog.Warn().Msgf("ACL rejection for ip %s", conn.RemoteAddr().String())
+		httpslog.Warn().Msgf("ACL rejection srcip=%s", conn.RemoteAddr().String())
 		conn.Close()
 		return nil
 	}
 	// check SNI against domainlist for an extra layer of security
 	if connInfo.Decision == acl.OriginIP {
-		httpslog.Warn().Msg("a client requested connection to " + sni + ", but it's not allowed as per configuration.. resetting TCP")
+		httpslog.Warn().Str("sni", sni).Str("srcip", conn.RemoteAddr().String()).Msg("connection request rejected since it's not allowed as per ACL.. resetting TCP")
 		conn.Close()
 		return nil
 	}
 	rPort := 443
 	var rAddr net.IP
 	if connInfo.Decision == acl.Override {
-		httpslog.Debug().Msgf("overriding destination IP %s with %s", rAddr.String(), connInfo.DstIP.String())
+		httpslog.Debug().Msgf("overriding destination IP %s with %s as per override ACL", rAddr.String(), connInfo.DstIP.String())
 		rAddr = connInfo.DstIP.IP
 		rPort = connInfo.DstIP.Port
 	} else {
@@ -62,7 +60,7 @@ func handle443(conn net.Conn) error {
 		}
 	}
 
-	httpslog.Info().Msgf("establishing connection to %s:%d from %s with SNI %s", rAddr.String(), rPort, conn.RemoteAddr().String(), sni)
+	httpslog.Debug().Str("sni", sni).Str("srcip", conn.RemoteAddr().String()).Str("dstip", rAddr.String()).Msg("connection request accepted")
 	// var target *net.TCPConn
 	var target net.Conn
 	// if the proxy is not set, or the destination IP is localhost, we'll use the OS's TCP stack and won't go through the SOCKS5 proxy
@@ -95,7 +93,7 @@ func handle443(conn net.Conn) error {
 }
 
 func runHTTPS(log zerolog.Logger) {
-	httpslog = log.With().Str("service", "https").Logger()
+	httpslog := log.With().Str("service", "https").Logger()
 	l, err := net.Listen("tcp", c.BindHTTPS)
 	if err != nil {
 		httpslog.Err(err)
@@ -107,8 +105,6 @@ func runHTTPS(log zerolog.Logger) {
 		if err != nil {
 			httpslog.Err(err)
 		}
-		go func() {
-			go handle443(c)
-		}()
+		go handle443(c, httpslog)
 	}
 }