logger

README.md

@@ -9,6 +9,6 @@
 - [x] cert
 - [x] https handler
 - [ ] http2
-- [ ] logger
+- [x] logger
 - [ ] 经内存转发 https 流量
-- [ ] 忽略某些错误例如：broken pipe, reset by peer, timeout
+- [x] 忽略某些错误例如：broken pipe, reset by peer, timeout

cert/cert.go

@@ -11,15 +11,17 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"math/big"
 	"os"
 	"path/filepath"
 	"time"
 
 	"github.com/golang/groupcache/lru"
+	_log "github.com/sirupsen/logrus"
 )
 
+var log = _log.WithField("at", "cert")
+
 // reference
 // https://docs.mitmproxy.org/stable/concepts-certificates/
 // https://github.com/mitmproxy/mitmproxy/blob/master/mitmproxy/certs.py
@@ -49,13 +51,14 @@ func NewCA(path string) (*CA, error) {
 			return nil, err
 		}
 	} else {
+		log.Debug("load root ca")
 		return ca, nil
 	}
 
-	log.Println("begin create ca")
 	if err := ca.create(); err != nil {
 		return nil, err
 	}
+	log.Debug("create root ca")
 
 	return ca, nil
 }

cmd/mitmproxy/main.go

@@ -1,13 +1,19 @@
 package main
 
 import (
-	"log"
+	"os"
 
 	"github.com/lqqyt2423/go-mitmproxy/proxy"
+	log "github.com/sirupsen/logrus"
 )
 
 func main() {
-	log.SetFlags(log.LstdFlags | log.Lshortfile)
+	log.SetLevel(log.InfoLevel)
+	log.SetReportCaller(false)
+	log.SetOutput(os.Stdout)
+	log.SetFormatter(&log.TextFormatter{
+		FullTimestamp: true,
+	})
 
 	opts := &proxy.Options{
 		Addr: ":9080",

go.mod

@@ -6,4 +6,5 @@ require (
 	github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e
 	github.com/golang/protobuf v1.4.3 // indirect
 	github.com/joho/godotenv v1.3.0
+	github.com/sirupsen/logrus v1.7.0
 )

go.sum

@@ -1,3 +1,4 @@
+github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e h1:1r7pUrabqp18hOBcwBwiTsbnFeTZHV9eER/QT5JVZxY=
 github.com/golang/groupcache v0.0.0-20200121045136-8c9f03a8e57e/go.mod h1:cIg4eruTrX1D+g88fzRXU5OdNfaM+9IcxsU14FzY7Hc=
 github.com/golang/protobuf v1.4.0-rc.1/go.mod h1:ceaxUfeHdC40wWswd/P6IGgMaK3YpKi5j83Wpe3EHw8=
@@ -12,6 +13,12 @@ github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMyw
 github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE=
 github.com/joho/godotenv v1.3.0 h1:Zjp+RcGpHhGlrMbJzXTrZZPrWj+1vfm90La1wgB6Bhc=
 github.com/joho/godotenv v1.3.0/go.mod h1:7hK45KPybAkOC6peb+G5yklZfMxEjkZhHbwpqxOKXbg=
+github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/sirupsen/logrus v1.7.0 h1:ShrD1U9pZB12TX0cVy0DtePoCH97K8EtX+mg7ZARUtM=
+github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
+github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037 h1:YyJpGZS1sBuBCzLAR1VEpK193GlqGZbnPFnPV/5Rsb4=
+golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=
 google.golang.org/protobuf v0.0.0-20200109180630-ec00e32a8dfd/go.mod h1:DFci5gLYBciE7Vtevhsrf46CRTquxDuWsQurQQe4oz8=
 google.golang.org/protobuf v0.0.0-20200221191635-4d8936d0db64/go.mod h1:kwYJMbMJ01Woi6D6+Kah6886xMZcty6N08ah7+eCXa0=

proxy/mitm.go

@@ -2,7 +2,6 @@ package proxy
 
 import (
 	"crypto/tls"
-	"log"
 	"net"
 	"net/http"
 	"time"
@@ -52,7 +51,7 @@ func NewMitmServer(proxy *Proxy) (Mitm, error) {
 		TLSNextProto: make(map[string]func(*http.Server, *tls.Conn, http.Handler)), // disable http2
 		TLSConfig: &tls.Config{
 			GetCertificate: func(chi *tls.ClientHelloInfo) (*tls.Certificate, error) {
-				// log.Printf("MitmServer GetCertificate ServerName: %v\n", chi.ServerName)
+				log.Debugf("MitmServer GetCertificate ServerName: %v\n", chi.ServerName)
 				return ca.GetCert(chi.ServerName)
 			},
 		},
@@ -70,7 +69,7 @@ func (m *MitmServer) Start() error {
 	}
 	m.Listener = ln
 	m.Server.Addr = ln.Addr().String()
-	log.Printf("MitmServer Server Addr is %v\n", m.Server.Addr)
+	log.Infof("MitmServer Server Addr is %v\n", m.Server.Addr)
 	defer ln.Close()
 
 	return m.Server.ServeTLS(ln, "", "")

proxy/proxy.go

@@ -3,14 +3,36 @@ package proxy
 import (
 	"crypto/tls"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"os"
+	"strings"
 	"sync"
 	"time"
+
+	_log "github.com/sirupsen/logrus"
 )
 
+var log = _log.WithField("at", "proxy")
+
+var ignoreErr = func(log *_log.Entry, err error) bool {
+	errs := err.Error()
+	strs := []string{
+		"read: connection reset by peer",
+		"write: broken pipe",
+		"i/o timeout",
+	}
+
+	for _, str := range strs {
+		if strings.Contains(errs, str) {
+			log.Debug(str)
+			return true
+		}
+	}
+
+	return false
+}
+
 type Options struct {
 	Addr string
 }
@@ -30,7 +52,7 @@ func (proxy *Proxy) Start() error {
 		}
 	}()
 
-	log.Printf("Proxy start listen at %v\n", proxy.Server.Addr)
+	log.Infof("Proxy start listen at %v\n", proxy.Server.Addr)
 	return proxy.Server.ListenAndServe()
 }
 
@@ -40,11 +62,16 @@ func (proxy *Proxy) ServeHTTP(res http.ResponseWriter, req *http.Request) {
 		return
 	}
 
+	log := log.WithFields(_log.Fields{
+		"in":  "ServeHTTP",
+		"url": req.URL,
+	})
+
 	if !req.URL.IsAbs() || req.URL.Host == "" {
 		res.WriteHeader(400)
 		_, err := io.WriteString(res, "此为代理服务器，不能直接发起请求")
 		if err != nil {
-			log.Printf("error: %v, url: %v\n", err, req.URL.String())
+			log.Error(err)
 		}
 		return
 	}
@@ -53,7 +80,7 @@ func (proxy *Proxy) ServeHTTP(res http.ResponseWriter, req *http.Request) {
 
 	proxyReq, err := http.NewRequest(req.Method, req.URL.String(), req.Body)
 	if err != nil {
-		log.Printf("error: %v, url: %v\n", err, req.URL.String())
+		log.Error(err)
 		res.WriteHeader(502)
 		return
 	}
@@ -65,7 +92,9 @@ func (proxy *Proxy) ServeHTTP(res http.ResponseWriter, req *http.Request) {
 	}
 	proxyRes, err := proxy.Client.Do(proxyReq)
 	if err != nil {
-		log.Printf("error: %v, url: %v\n", err, req.URL.String())
+		if !ignoreErr(log, err) {
+			log.Error(err)
+		}
 		res.WriteHeader(502)
 		return
 	}
@@ -78,21 +107,26 @@ func (proxy *Proxy) ServeHTTP(res http.ResponseWriter, req *http.Request) {
 	}
 	res.WriteHeader(proxyRes.StatusCode)
 	_, err = io.Copy(res, proxyRes.Body)
-	if err != nil {
+	if err != nil && !ignoreErr(log, err) {
-		log.Printf("error: %v, url: %v\n", err, req.URL.String())
+		log.Error(err)
 		return
 	}
 
-	log.Printf("%v %v %v - %v ms", req.Method, req.URL.String(), proxyRes.StatusCode, time.Since(start).Milliseconds())
+	log.Infof("%v %v %v - %v ms", req.Method, req.URL.String(), proxyRes.StatusCode, time.Since(start).Milliseconds())
 }
 
 func (proxy *Proxy) handleConnect(res http.ResponseWriter, req *http.Request) {
-	// log.Printf("CONNECT: %v\n", req.Host)
+	log := log.WithFields(_log.Fields{
+		"in":   "handleConnect",
+		"host": req.Host,
+	})
+
+	log.Debug("CONNECT")
 
 	conn, err := proxy.Mitm.Dial(req.Host)
 
 	if err != nil {
-		log.Printf("error: %v, host: %v\n", err, req.Host)
+		log.Error(err)
 		res.WriteHeader(502)
 		return
 	}
@@ -100,7 +134,7 @@ func (proxy *Proxy) handleConnect(res http.ResponseWriter, req *http.Request) {
 
 	cconn, _, err := res.(http.Hijacker).Hijack()
 	if err != nil {
-		log.Printf("error: %v, host: %v\n", err, req.Host)
+		log.Error(err)
 		res.WriteHeader(502)
 		return
 	}
@@ -108,22 +142,22 @@ func (proxy *Proxy) handleConnect(res http.ResponseWriter, req *http.Request) {
 
 	_, err = io.WriteString(cconn, "HTTP/1.1 200 Connection Established\r\n\r\n")
 	if err != nil {
-		log.Printf("error: %v, host: %v\n", err, req.Host)
+		log.Error(err)
 		return
 	}
 
 	ch := make(chan bool)
 	go func() {
 		_, err := io.Copy(conn, cconn)
-		if err != nil {
+		if err != nil && !ignoreErr(log, err) {
-			log.Printf("error: %v, host: %v\n", err, req.Host)
+			log.Error(err)
 		}
 		ch <- true
 	}()
 
 	_, err = io.Copy(cconn, conn)
-	if err != nil {
+	if err != nil && !ignoreErr(log, err) {
-		log.Printf("error: %v, host: %v\n", err, req.Host)
+		log.Error(err)
 	}
 
 	<-ch
@@ -180,7 +214,7 @@ func GetTlsKeyLogWriter() io.Writer {
 
 		writer, err := os.OpenFile(logfile, os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0666)
 		if err != nil {
-			log.Printf("GetTlsKeyLogWriter error: %v\n", err)
+			log.WithField("in", "GetTlsKeyLogWriter").Debug(err)
 			return
 		}