From 75f5cb9afb28cfd638b5b8c8f709bc609225a995 Mon Sep 17 00:00:00 2001 From: Darien Raymond Date: Thu, 6 Apr 2017 21:13:17 +0200 Subject: [PATCH] refactor log and error --- app/dns/config.go | 3 ++- app/dns/server/nameserver.go | 6 +++--- app/dns/server/server.go | 4 ++-- app/log/log.go | 26 ++++++++++++------------- app/proxyman/inbound/always.go | 3 ++- app/proxyman/inbound/dynamic.go | 7 ++++--- app/proxyman/mux/mux.go | 22 ++++++++++----------- app/proxyman/outbound/handler.go | 2 +- app/router/router.go | 2 +- common/errors/errors_test.go | 24 ++++++++++++++++++++++- common/net/address.go | 3 ++- proxy/dokodemo/dokodemo.go | 14 +++++-------- proxy/freedom/freedom.go | 16 +++++++-------- proxy/http/server.go | 6 +++--- proxy/shadowsocks/client.go | 2 +- proxy/socks/server.go | 10 +++++----- proxy/vmess/account.go | 3 ++- proxy/vmess/encoding/client.go | 6 +++--- proxy/vmess/inbound/inbound.go | 8 ++++---- proxy/vmess/outbound/outbound.go | 2 +- testing/scenarios/common.go | 5 +++-- tools/conf/router.go | 2 +- transport/internet/kcp/connection.go | 10 +++++----- transport/internet/kcp/dialer.go | 4 ++-- transport/internet/kcp/listener.go | 4 ++-- transport/internet/tcp/dialer.go | 2 +- transport/internet/tcp/hub.go | 4 ++-- transport/internet/tcp/sockopt_linux.go | 6 +++--- transport/internet/tls/config.go | 3 ++- transport/internet/udp/dispatcher.go | 5 +++-- transport/internet/udp/hub.go | 4 ++-- transport/internet/websocket/dialer.go | 2 +- transport/internet/websocket/hub.go | 2 +- 33 files changed, 123 insertions(+), 99 deletions(-) diff --git a/app/dns/config.go b/app/dns/config.go index 2565b4511..5bbf55fcc 100644 --- a/app/dns/config.go +++ b/app/dns/config.go @@ -4,6 +4,7 @@ import ( "net" "v2ray.com/core/app/log" + "v2ray.com/core/common/errors" ) func (v *Config) GetInternalHosts() map[string]net.IP { @@ -11,7 +12,7 @@ func (v *Config) GetInternalHosts() map[string]net.IP { for domain, ipOrDomain := range v.GetHosts() { address := ipOrDomain.AsAddress() if address.Family().IsDomain() { - log.Warning("DNS: Ignoring domain address in static hosts: ", address.Domain()) + log.Trace(errors.New("DNS: Ignoring domain address in static hosts: ", address.Domain()).AtWarning()) continue } hosts[domain] = address.IP() diff --git a/app/dns/server/nameserver.go b/app/dns/server/nameserver.go index 1167e8c12..57195e7f7 100644 --- a/app/dns/server/nameserver.go +++ b/app/dns/server/nameserver.go @@ -89,7 +89,7 @@ func (v *UDPNameServer) AssignUnusedID(response chan<- *ARecord) uint16 { if _, found := v.requests[id]; found { continue } - log.Debug("DNS: Add pending request id ", id) + log.Trace(errors.New("DNS: Add pending request id ", id).AtDebug()) v.requests[id] = &PendingRequest{ expire: time.Now().Add(time.Second * 8), response: response, @@ -105,7 +105,7 @@ func (v *UDPNameServer) HandleResponse(payload *buf.Buffer) { msg := new(dns.Msg) err := msg.Unpack(payload.Bytes()) if err != nil { - log.Warning("DNS: Failed to parse DNS response: ", err) + log.Trace(errors.New("DNS: Failed to parse DNS response: ", err).AtWarning()) return } record := &ARecord{ @@ -113,7 +113,7 @@ func (v *UDPNameServer) HandleResponse(payload *buf.Buffer) { } id := msg.Id ttl := DefaultTTL - log.Debug("DNS: Handling response for id ", id, " content: ", msg.String()) + log.Trace(errors.New("DNS: Handling response for id ", id, " content: ", msg.String()).AtDebug()) v.Lock() request, found := v.requests[id] diff --git a/app/dns/server/server.go b/app/dns/server/server.go index 810031156..aadfb3770 100644 --- a/app/dns/server/server.go +++ b/app/dns/server/server.go @@ -113,13 +113,13 @@ func (v *CacheServer) Get(domain string) []net.IP { A: a, } v.Unlock() - log.Debug("DNS: Returning ", len(a.IPs), " IPs for domain ", domain) + log.Trace(errors.New("DNS: Returning ", len(a.IPs), " IPs for domain ", domain).AtDebug()) return a.IPs case <-time.After(QueryTimeout): } } - log.Debug("DNS: Returning nil for domain ", domain) + log.Trace(errors.New("DNS: Returning nil for domain ", domain).AtDebug()) return nil } diff --git a/app/log/log.go b/app/log/log.go index f71caf90f..ab4bab41f 100644 --- a/app/log/log.go +++ b/app/log/log.go @@ -49,32 +49,32 @@ func InitErrorLogger(file string) error { return nil } -// Debug outputs a debug log with given format and optional arguments. -func Debug(val ...interface{}) { +// writeDebug outputs a debug log with given format and optional arguments. +func writeDebug(val ...interface{}) { debugLogger.Log(&internal.ErrorLog{ Prefix: "[Debug]", Values: val, }) } -// Info outputs an info log with given format and optional arguments. -func Info(val ...interface{}) { +// writeInfo outputs an info log with given format and optional arguments. +func writeInfo(val ...interface{}) { infoLogger.Log(&internal.ErrorLog{ Prefix: "[Info]", Values: val, }) } -// Warning outputs a warning log with given format and optional arguments. -func Warning(val ...interface{}) { +// writeWarning outputs a warning log with given format and optional arguments. +func writeWarning(val ...interface{}) { warningLogger.Log(&internal.ErrorLog{ Prefix: "[Warning]", Values: val, }) } -// Error outputs an error log with given format and optional arguments. -func Error(val ...interface{}) { +// writeError outputs an error log with given format and optional arguments. +func writeError(val ...interface{}) { errorLogger.Log(&internal.ErrorLog{ Prefix: "[Error]", Values: val, @@ -85,15 +85,15 @@ func Trace(err error) { s := errors.GetSeverity(err) switch s { case errors.SeverityDebug: - Debug(err) + writeDebug(err) case errors.SeverityInfo: - Info(err) + writeInfo(err) case errors.SeverityWarning: - Warning(err) + writeWarning(err) case errors.SeverityError: - Error(err) + writeError(err) default: - Info(err) + writeInfo(err) } } diff --git a/app/proxyman/inbound/always.go b/app/proxyman/inbound/always.go index 4bfede025..c89771c80 100644 --- a/app/proxyman/inbound/always.go +++ b/app/proxyman/inbound/always.go @@ -7,6 +7,7 @@ import ( "v2ray.com/core/app/proxyman" "v2ray.com/core/app/proxyman/mux" "v2ray.com/core/common/dice" + "v2ray.com/core/common/errors" "v2ray.com/core/common/net" "v2ray.com/core/proxy" ) @@ -36,7 +37,7 @@ func NewAlwaysOnInboundHandler(ctx context.Context, tag string, receiverConfig * } for port := pr.From; port <= pr.To; port++ { if nl.HasNetwork(net.Network_TCP) { - log.Debug("Proxyman|DefaultInboundHandler: creating tcp worker on ", address, ":", port) + log.Trace(errors.New("Proxyman|DefaultInboundHandler: creating tcp worker on ", address, ":", port).AtDebug()) worker := &tcpWorker{ address: address, port: net.Port(port), diff --git a/app/proxyman/inbound/dynamic.go b/app/proxyman/inbound/dynamic.go index 393f0359e..2bc84a5af 100644 --- a/app/proxyman/inbound/dynamic.go +++ b/app/proxyman/inbound/dynamic.go @@ -9,6 +9,7 @@ import ( "v2ray.com/core/app/proxyman" "v2ray.com/core/app/proxyman/mux" "v2ray.com/core/common/dice" + "v2ray.com/core/common/errors" v2net "v2ray.com/core/common/net" "v2ray.com/core/proxy" ) @@ -92,7 +93,7 @@ func (h *DynamicInboundHandler) refresh() error { port := h.allocatePort() p, err := proxy.CreateInboundHandler(ctx, h.proxyConfig) if err != nil { - log.Warning("Proxyman|DefaultInboundHandler: Failed to create proxy instance: ", err) + log.Trace(errors.New("failed to create proxy instance").Base(err).Path("Proxyman", "Inbound", "DynamicInboundHandler").AtWarning()) continue } nl := p.Network() @@ -107,7 +108,7 @@ func (h *DynamicInboundHandler) refresh() error { dispatcher: h.mux, } if err := worker.Start(); err != nil { - log.Warning("Proxyman:InboundHandler: Failed to create TCP worker: ", err) + log.Trace(errors.New("Proxyman:InboundHandler: Failed to create TCP worker: ", err).AtWarning()) continue } workers = append(workers, worker) @@ -123,7 +124,7 @@ func (h *DynamicInboundHandler) refresh() error { dispatcher: h.mux, } if err := worker.Start(); err != nil { - log.Warning("Proxyman:InboundHandler: Failed to create UDP worker: ", err) + log.Trace(errors.New("Proxyman:InboundHandler: Failed to create UDP worker: ", err).AtWarning()) continue } workers = append(workers, worker) diff --git a/app/proxyman/mux/mux.go b/app/proxyman/mux/mux.go index c64827df1..60ce55a5e 100644 --- a/app/proxyman/mux/mux.go +++ b/app/proxyman/mux/mux.go @@ -200,16 +200,16 @@ func fetchInput(ctx context.Context, s *session, output buf.Writer) { defer writer.Close() defer s.closeUplink() - log.Info("Proxyman|Mux|Client: Dispatching request to ", dest) + log.Trace(errors.New("dispatching request to ", dest).Path("Proxyman", "Mux", "Client")) data, _ := s.input.ReadTimeout(time.Millisecond * 500) if data != nil { if err := writer.Write(data); err != nil { - log.Info("Proxyman|Mux|Client: Failed to write first payload: ", err) + log.Trace(errors.New("failed to write first payload").Base(err).Path("Proxyman", "Mux", "Client")) return } } if err := buf.PipeUntilEOF(signal.BackgroundTimer(), s.input, writer); err != nil { - log.Info("Proxyman|Mux|Client: Failed to fetch all input: ", err) + log.Trace(errors.New("failed to fetch all input").Base(err).Path("Proxyman", "Mux", "Client")) } } @@ -287,7 +287,7 @@ func (m *Client) fetchOutput() { for { meta, err := reader.ReadMetadata() if err != nil { - log.Info("Proxyman|Mux|Client: Failed to read metadata: ", err) + log.Trace(errors.New("failed to read metadata").Base(err).Path("Proxyman", "Mux", "Client")) break } m.access.RLock() @@ -308,7 +308,7 @@ func (m *Client) fetchOutput() { } if err != nil { - log.Info("Proxyman|Mux|Client: Failed to read data: ", err) + log.Trace(errors.New("failed to read data").Base(err).Path("Proxyman", "Mux", "Client")) break } } @@ -324,7 +324,7 @@ func NewServer(ctx context.Context) *Server { space.OnInitialize(func() error { d := dispatcher.FromSpace(space) if d == nil { - return errors.New("Proxyman|Mux: No dispatcher in space.") + return errors.New("no dispatcher in space").Path("Proxyman", "Mux", "Server") } s.dispatcher = d return nil @@ -363,7 +363,7 @@ func (w *ServerWorker) remove(id uint16) { func handle(ctx context.Context, s *session, output buf.Writer) { writer := NewResponseWriter(s.id, output) if err := buf.PipeUntilEOF(signal.BackgroundTimer(), s.input, writer); err != nil { - log.Info("Proxyman|Mux|ServerWorker: Session ", s.id, " ends: ", err) + log.Trace(errors.New("session ", s.id, " ends: ").Base(err).Path("Proxyman", "Mux", "ServerWorker")) } writer.Close() s.closeDownlink() @@ -381,7 +381,7 @@ func (w *ServerWorker) run(ctx context.Context) { meta, err := reader.ReadMetadata() if err != nil { - log.Info("Proxyman|Mux|ServerWorker: Failed to read metadata: ", err) + log.Trace(errors.New("failed to read metadata").Base(err).Path("Proxyman", "Mux", "ServerWorker")) return } @@ -395,10 +395,10 @@ func (w *ServerWorker) run(ctx context.Context) { } if meta.SessionStatus == SessionStatusNew { - log.Info("Proxyman|Mux|Server: Received request for ", meta.Target) + log.Trace(errors.New("received request for ", meta.Target).Path("Proxyman", "Mux", "ServerWorker")) inboundRay, err := w.dispatcher.Dispatch(ctx, meta.Target) if err != nil { - log.Info("Proxyman|Mux: Failed to dispatch request: ", err) + log.Trace(errors.New("failed to dispatch request.").Base(err).Path("Proxymann", "Mux", "ServerWorker")) continue } s = &session{ @@ -424,7 +424,7 @@ func (w *ServerWorker) run(ctx context.Context) { } if err != nil { - log.Info("Proxyman|Mux|ServerWorker: Failed to read data: ", err) + log.Trace(errors.New("failed to read data").Base(err).Path("Proxymann", "Mux", "ServerWorker")) break } } diff --git a/app/proxyman/outbound/handler.go b/app/proxyman/outbound/handler.go index 8f2d9c5a2..eabffe3a3 100644 --- a/app/proxyman/outbound/handler.go +++ b/app/proxyman/outbound/handler.go @@ -102,7 +102,7 @@ func (h *Handler) Dial(ctx context.Context, dest v2net.Destination) (internet.Co return NewConnection(stream), nil } - log.Warning("Proxyman|OutboundHandler: Failed to get outbound handler with tag: ", tag) + log.Trace(errors.New("Proxyman|OutboundHandler: Failed to get outbound handler with tag: ", tag).AtWarning()) } if h.senderSettings.Via != nil { diff --git a/app/router/router.go b/app/router/router.go index 76b077a8d..36a258143 100644 --- a/app/router/router.go +++ b/app/router/router.go @@ -76,7 +76,7 @@ func (v *Router) TakeDetour(ctx context.Context) (string, error) { } if v.domainStrategy == Config_IpIfNonMatch && dest.Address.Family().IsDomain() { - log.Info("Router: Looking up IP for ", dest) + log.Trace(errors.New("looking up IP for ", dest).Path("App", "Router")) ipDests := v.resolveIP(dest) if ipDests != nil { ctx = proxy.ContextWithResolveIPs(ctx, ipDests) diff --git a/common/errors/errors_test.go b/common/errors/errors_test.go index a1f4e3f48..cb385fbd9 100644 --- a/common/errors/errors_test.go +++ b/common/errors/errors_test.go @@ -8,7 +8,7 @@ import ( "v2ray.com/core/testing/assert" ) -func TestActionRequired(t *testing.T) { +func TestError(t *testing.T) { assert := assert.On(t) err := New("TestError") @@ -25,3 +25,25 @@ func TestActionRequired(t *testing.T) { assert.Bool(GetSeverity(err) == SeverityWarning).IsTrue() assert.String(err.Error()).Contains("EOF") } + +func TestErrorMessage(t *testing.T) { + assert := assert.On(t) + + data := []struct { + err error + msg string + }{ + { + err: New("a").Base(New("b")).Path("c", "d", "e"), + msg: "c|d|e: a > b", + }, + { + err: New("a").Base(New("b").Path("c")).Path("d", "e"), + msg: "d|e: a > c: b", + }, + } + + for _, d := range data { + assert.String(d.err.Error()).Equals(d.msg) + } +} diff --git a/common/net/address.go b/common/net/address.go index bb7a6466e..e86b88189 100644 --- a/common/net/address.go +++ b/common/net/address.go @@ -4,6 +4,7 @@ import ( "net" "v2ray.com/core/app/log" + "v2ray.com/core/common/errors" "v2ray.com/core/common/predicate" ) @@ -94,7 +95,7 @@ func IPAddress(ip []byte) Address { } return addr default: - log.Error("Net: Invalid IP format: ", ip) + log.Trace(errors.New("Net: Invalid IP format: ", ip).AtError()) return nil } } diff --git a/proxy/dokodemo/dokodemo.go b/proxy/dokodemo/dokodemo.go index fa2cc3ea1..eca4ceaca 100644 --- a/proxy/dokodemo/dokodemo.go +++ b/proxy/dokodemo/dokodemo.go @@ -44,7 +44,7 @@ func (d *DokodemoDoor) Network() net.NetworkList { } func (d *DokodemoDoor) Process(ctx context.Context, network net.Network, conn internet.Connection, dispatcher dispatcher.Interface) error { - log.Debug("Dokodemo: processing connection from: ", conn.RemoteAddr()) + log.Trace(errors.New("Dokodemo: processing connection from: ", conn.RemoteAddr()).AtDebug()) conn.SetReusable(false) dest := net.Destination{ Network: network, @@ -57,8 +57,7 @@ func (d *DokodemoDoor) Process(ctx context.Context, network net.Network, conn in } } if !dest.IsValid() || dest.Address == nil { - log.Info("Dokodemo: Invalid destination. Discarding...") - return errors.New("Dokodemo: Unable to get destination.") + return errors.New("unable to get destination").Path("Proxy", "Dokodemo") } timeout := time.Second * time.Duration(d.config.Timeout) @@ -78,8 +77,7 @@ func (d *DokodemoDoor) Process(ctx context.Context, network net.Network, conn in chunkReader := buf.NewReader(conn) if err := buf.PipeUntilEOF(timer, chunkReader, inboundRay.InboundInput()); err != nil { - log.Info("Dokodemo: Failed to transport request: ", err) - return err + return errors.New("failed to transport request").Base(err).Path("Proxy", "Dokodemo") } return nil @@ -89,8 +87,7 @@ func (d *DokodemoDoor) Process(ctx context.Context, network net.Network, conn in v2writer := buf.NewWriter(conn) if err := buf.PipeUntilEOF(timer, inboundRay.InboundOutput(), v2writer); err != nil { - log.Info("Dokodemo: Failed to transport response: ", err) - return err + return errors.New("failed to transport response").Base(err).Path("Proxy", "Dokodemo") } return nil }) @@ -98,8 +95,7 @@ func (d *DokodemoDoor) Process(ctx context.Context, network net.Network, conn in if err := signal.ErrorOrFinish2(ctx, requestDone, responseDone); err != nil { inboundRay.InboundInput().CloseError() inboundRay.InboundOutput().CloseError() - log.Info("Dokodemo: Connection ends with ", err) - return err + return errors.New("connection ends").Base(err).Path("Proxy", "Dokodemo") } runtime.KeepAlive(timer) diff --git a/proxy/freedom/freedom.go b/proxy/freedom/freedom.go index 833ef2405..260299501 100644 --- a/proxy/freedom/freedom.go +++ b/proxy/freedom/freedom.go @@ -31,7 +31,7 @@ type Handler struct { func New(ctx context.Context, config *Config) (*Handler, error) { space := app.SpaceFromContext(ctx) if space == nil { - return nil, errors.New("Freedom: No space in context.") + return nil, errors.New("no space in context").Path("Proxy", "Freedom") } f := &Handler{ domainStrategy: config.DomainStrategy, @@ -42,7 +42,7 @@ func New(ctx context.Context, config *Config) (*Handler, error) { if config.DomainStrategy == Config_USE_IP { f.dns = dns.FromSpace(space) if f.dns == nil { - return errors.New("Freedom: DNS server is not found in the space.") + return errors.New("DNS server is not found in the space").Path("Proxy", "Freedom") } } return nil @@ -50,7 +50,6 @@ func New(ctx context.Context, config *Config) (*Handler, error) { return f, nil } -// Private: Visible for testing. func (v *Handler) ResolveIP(destination net.Destination) net.Destination { if !destination.Address.Family().IsDomain() { return destination @@ -58,7 +57,7 @@ func (v *Handler) ResolveIP(destination net.Destination) net.Destination { ips := v.dns.Get(destination.Address.Domain()) if len(ips) == 0 { - log.Info("Freedom: DNS returns nil answer. Keep domain as is.") + log.Trace(errors.New("DNS returns nil answer. Keep domain as is.").Path("Proxy", "Freedom")) return destination } @@ -69,7 +68,7 @@ func (v *Handler) ResolveIP(destination net.Destination) net.Destination { } else { newDest = net.UDPDestination(net.IPAddress(ip), destination.Port) } - log.Info("Freedom: Changing destination from ", destination, " to ", newDest) + log.Trace(errors.New("changing destination from ", destination, " to ", newDest).Path("Proxy", "Freedom")) return newDest } @@ -83,7 +82,7 @@ func (v *Handler) Process(ctx context.Context, outboundRay ray.OutboundRay, dial Port: net.Port(server.Port), } } - log.Info("Freedom: Opening connection to ", destination) + log.Trace(errors.New("opening connection to ", destination).Path("Proxy", "Freedom")) input := outboundRay.OutboundInput() output := outboundRay.OutboundOutput() @@ -102,7 +101,7 @@ func (v *Handler) Process(ctx context.Context, outboundRay ray.OutboundRay, dial return nil }) if err != nil { - return errors.New("failed to open connection to ", destination).Base(err).Path("Freedom") + return errors.New("failed to open connection to ", destination).Base(err).Path("Proxy", "Freedom") } defer conn.Close() @@ -112,7 +111,6 @@ func (v *Handler) Process(ctx context.Context, outboundRay ray.OutboundRay, dial if timeout == 0 { timeout = time.Minute * 5 } - log.Debug("Freedom: Cancel after ", timeout) ctx, timer := signal.CancelAfterInactivity(ctx, timeout) requestDone := signal.ExecuteAsync(func() error { @@ -136,7 +134,7 @@ func (v *Handler) Process(ctx context.Context, outboundRay ray.OutboundRay, dial if err := signal.ErrorOrFinish2(ctx, requestDone, responseDone); err != nil { input.CloseError() output.CloseError() - return errors.New("connection ends").Base(err).Path("Freedom") + return errors.New("connection ends").Base(err).Path("Proxy", "Freedom") } runtime.KeepAlive(timer) diff --git a/proxy/http/server.go b/proxy/http/server.go index f7c86a848..ac2487dbf 100644 --- a/proxy/http/server.go +++ b/proxy/http/server.go @@ -77,11 +77,11 @@ func (s *Server) Process(ctx context.Context, network v2net.Network, conn intern request, err := http.ReadRequest(reader) if err != nil { if errors.Cause(err) != io.EOF { - log.Warning("HTTP: Failed to read http request: ", err) + log.Trace(errors.New("HTTP: Failed to read http request: ", err).AtWarning()) } return err } - log.Info("HTTP: Request to Method [", request.Method, "] Host [", request.Host, "] with URL [", request.URL, "]") + log.Trace(errors.New("request to Method [", request.Method, "] Host [", request.Host, "] with URL [", request.URL, "]").Path("Proxy", "HTTP", "Server")) conn.SetReadDeadline(time.Time{}) defaultPort := v2net.Port(80) @@ -234,7 +234,7 @@ func (s *Server) handlePlainHTTP(ctx context.Context, request *http.Request, rea responseReader := bufio.NewReader(buf.ToBytesReader(ray.InboundOutput())) response, err := http.ReadResponse(responseReader, request) if err != nil { - log.Warning("HTTP: Failed to read response: ", err) + log.Trace(errors.New("HTTP: Failed to read response: ", err).AtWarning()) response = generateResponse(503, "Service Unavailable") } responseWriter := buf.NewBufferedWriter(writer) diff --git a/proxy/shadowsocks/client.go b/proxy/shadowsocks/client.go index a7e408d10..8dae10579 100644 --- a/proxy/shadowsocks/client.go +++ b/proxy/shadowsocks/client.go @@ -62,7 +62,7 @@ func (v *Client) Process(ctx context.Context, outboundRay ray.OutboundRay, diale if err != nil { return errors.New("failed to find an available destination").AtWarning().Base(err).Path("Shadowsocks", "Client") } - log.Info("Shadowsocks|Client: Tunneling request to ", destination, " via ", server.Destination()) + log.Trace(errors.New("Shadowsocks|Client: Tunneling request to ", destination, " via ", server.Destination())) defer conn.Close() conn.SetReusable(false) diff --git a/proxy/socks/server.go b/proxy/socks/server.go index 8ec94b425..dbc8431ba 100644 --- a/proxy/socks/server.go +++ b/proxy/socks/server.go @@ -78,14 +78,14 @@ func (s *Server) processTCP(ctx context.Context, conn internet.Connection, dispa if source, ok := proxy.SourceFromContext(ctx); ok { log.Access(source, "", log.AccessRejected, err) } - log.Info("Socks|Server: Failed to read request: ", err) + log.Trace(errors.New("Socks|Server: Failed to read request: ", err)) return err } conn.SetReadDeadline(time.Time{}) if request.Command == protocol.RequestCommandTCP { dest := request.Destination() - log.Info("Socks|Server: TCP Connect request to ", dest) + log.Trace(errors.New("Socks|Server: TCP Connect request to ", dest)) if source, ok := proxy.SourceFromContext(ctx); ok { log.Access(source, dest, log.AccessAccepted, "") } @@ -169,7 +169,7 @@ func (v *Server) handleUDPPayload(ctx context.Context, conn internet.Connection, request, data, err := DecodeUDPPacket(payload.Bytes()) if err != nil { - log.Info("Socks|Server: Failed to parse UDP request: ", err) + log.Trace(errors.New("Socks|Server: Failed to parse UDP request: ", err)) continue } @@ -177,7 +177,7 @@ func (v *Server) handleUDPPayload(ctx context.Context, conn internet.Connection, continue } - log.Info("Socks: Send packet to ", request.Destination(), " with ", len(data), " bytes") + log.Trace(errors.New("Socks: Send packet to ", request.Destination(), " with ", len(data), " bytes")) if source, ok := proxy.SourceFromContext(ctx); ok { log.Access(source, request.Destination, log.AccessAccepted, "") } @@ -187,7 +187,7 @@ func (v *Server) handleUDPPayload(ctx context.Context, conn internet.Connection, udpServer.Dispatch(ctx, request.Destination(), dataBuf, func(payload *buf.Buffer) { defer payload.Release() - log.Info("Socks|Server: Writing back UDP response with ", payload.Len(), " bytes") + log.Trace(errors.New("Socks|Server: Writing back UDP response with ", payload.Len(), " bytes")) udpMessage := EncodeUDPPacket(request, payload.Bytes()) defer udpMessage.Release() diff --git a/proxy/vmess/account.go b/proxy/vmess/account.go index 7d9dca47e..6e032f20a 100644 --- a/proxy/vmess/account.go +++ b/proxy/vmess/account.go @@ -3,6 +3,7 @@ package vmess import ( "v2ray.com/core/app/log" "v2ray.com/core/common/dice" + "v2ray.com/core/common/errors" "v2ray.com/core/common/protocol" "v2ray.com/core/common/uuid" ) @@ -32,7 +33,7 @@ func (v *InternalAccount) Equals(account protocol.Account) bool { func (v *Account) AsAccount() (protocol.Account, error) { id, err := uuid.ParseString(v.Id) if err != nil { - log.Error("VMess: Failed to parse ID: ", err) + log.Trace(errors.New("failed to parse ID").Path("VMess", "Account").Base(err).AtError()) return nil, err } protoID := protocol.NewID(id) diff --git a/proxy/vmess/encoding/client.go b/proxy/vmess/encoding/client.go index cb852ccf8..dc01f2a0e 100644 --- a/proxy/vmess/encoding/client.go +++ b/proxy/vmess/encoding/client.go @@ -63,7 +63,7 @@ func (v *ClientSession) EncodeRequestHeader(header *protocol.RequestHeader, writ timestamp := protocol.NewTimestampGenerator(protocol.NowTime(), 30)() account, err := header.User.GetTypedAccount() if err != nil { - log.Error("VMess: Failed to get user account: ", err) + log.Trace(errors.New("VMess: Failed to get user account: ", err).AtError()) return } idHash := v.idHash(account.(*vmess.InternalAccount).AnyValidID().Bytes()) @@ -186,7 +186,7 @@ func (v *ClientSession) DecodeResponseHeader(reader io.Reader) (*protocol.Respon _, err := io.ReadFull(v.responseReader, buffer[:4]) if err != nil { - log.Info("VMess|Client: Failed to read response header: ", err) + log.Trace(errors.New("VMess|Client: Failed to read response header: ", err)) return nil, err } @@ -203,7 +203,7 @@ func (v *ClientSession) DecodeResponseHeader(reader io.Reader) (*protocol.Respon dataLen := int(buffer[3]) _, err := io.ReadFull(v.responseReader, buffer[:dataLen]) if err != nil { - log.Info("VMess|Client: Failed to read response command: ", err) + log.Trace(errors.New("VMess|Client: Failed to read response command: ", err)) return nil, err } data := buffer[:dataLen] diff --git a/proxy/vmess/inbound/inbound.go b/proxy/vmess/inbound/inbound.go index 36164fde5..8a7fdc624 100644 --- a/proxy/vmess/inbound/inbound.go +++ b/proxy/vmess/inbound/inbound.go @@ -179,13 +179,13 @@ func (v *Handler) Process(ctx context.Context, network net.Network, connection i if err != nil { if errors.Cause(err) != io.EOF { log.Access(connection.RemoteAddr(), "", log.AccessRejected, err) - log.Info("VMess|Inbound: Invalid request from ", connection.RemoteAddr(), ": ", err) + log.Trace(errors.New("VMess|Inbound: Invalid request from ", connection.RemoteAddr(), ": ", err)) } connection.SetReusable(false) return err } log.Access(connection.RemoteAddr(), request.Destination(), log.AccessAccepted, "") - log.Info("VMess|Inbound: Received request for ", request.Destination()) + log.Trace(errors.New("VMess|Inbound: Received request for ", request.Destination())) connection.SetReadDeadline(time.Time{}) @@ -245,7 +245,7 @@ func (v *Handler) generateCommand(ctx context.Context, request *protocol.Request if v.inboundHandlerManager != nil { handler, err := v.inboundHandlerManager.GetHandler(ctx, tag) if err != nil { - log.Warning("VMess|Inbound: Failed to get detour handler: ", tag, err) + log.Trace(errors.New("VMess|Inbound: Failed to get detour handler: ", tag, err).AtWarning()) return nil } proxyHandler, port, availableMin := handler.GetRandomInboundProxy() @@ -255,7 +255,7 @@ func (v *Handler) generateCommand(ctx context.Context, request *protocol.Request availableMin = 255 } - log.Info("VMess|Inbound: Pick detour handler for port ", port, " for ", availableMin, " minutes.") + log.Trace(errors.New("VMess|Inbound: Pick detour handler for port ", port, " for ", availableMin, " minutes.")) user := inboundHandler.GetUser(request.User.Email) if user == nil { return nil diff --git a/proxy/vmess/outbound/outbound.go b/proxy/vmess/outbound/outbound.go index 041fd5317..9931a5455 100644 --- a/proxy/vmess/outbound/outbound.go +++ b/proxy/vmess/outbound/outbound.go @@ -69,7 +69,7 @@ func (v *Handler) Process(ctx context.Context, outboundRay ray.OutboundRay, dial if !ok { return errors.New("VMess|Outbound: Target not specified.") } - log.Info("VMess|Outbound: Tunneling request to ", target, " via ", rec.Destination()) + log.Trace(errors.New("VMess|Outbound: Tunneling request to ", target, " via ", rec.Destination())) command := protocol.RequestCommandTCP if target.Network == net.Network_UDP { diff --git a/testing/scenarios/common.go b/testing/scenarios/common.go index 148dd0012..4f9ba4f51 100644 --- a/testing/scenarios/common.go +++ b/testing/scenarios/common.go @@ -16,6 +16,7 @@ import ( "v2ray.com/core" "v2ray.com/core/app/log" "v2ray.com/core/common" + "v2ray.com/core/common/errors" v2net "v2ray.com/core/common/net" "v2ray.com/core/common/retry" ) @@ -106,11 +107,11 @@ func GetSourcePath() string { } func CloseAllServers() { - log.Info("Closing all servers.") + log.Trace(errors.New("Closing all servers.")) for _, server := range runningServers { server.Process.Signal(os.Interrupt) server.Process.Wait() } runningServers = make([]*exec.Cmd, 0, 10) - log.Info("All server closed.") + log.Trace(errors.New("All server closed.")) } diff --git a/tools/conf/router.go b/tools/conf/router.go index f3e2ac5ce..e0e09cbdb 100644 --- a/tools/conf/router.go +++ b/tools/conf/router.go @@ -228,7 +228,7 @@ func parseChinaSitesRule(data []byte) (*router.RoutingRule, error) { rawRule := new(RouterRule) err := json.Unmarshal(data, rawRule) if err != nil { - log.Error("Router: Invalid router rule: ", err) + log.Trace(errors.New("Router: Invalid router rule: ", err).AtError()) return nil, err } return &router.RoutingRule{ diff --git a/transport/internet/kcp/connection.go b/transport/internet/kcp/connection.go index 19b44ca5d..baedeb0b1 100644 --- a/transport/internet/kcp/connection.go +++ b/transport/internet/kcp/connection.go @@ -203,7 +203,7 @@ type Connection struct { // NewConnection create a new KCP connection between local and remote. func NewConnection(conv uint16, sysConn SystemConnection, recycler internal.ConnectionRecyler, config *Config) *Connection { - log.Info("KCP|Connection: creating connection ", conv) + log.Trace(errors.New("KCP|Connection: creating connection ", conv)) conn := &Connection{ conv: conv, @@ -341,7 +341,7 @@ func (v *Connection) SetState(state State) { current := v.Elapsed() atomic.StoreInt32((*int32)(&v.state), int32(state)) atomic.StoreUint32(&v.stateBeginTime, current) - log.Debug("KCP|Connection: #", v.conv, " entering state ", state, " at ", current) + log.Trace(errors.New("KCP|Connection: #", v.conv, " entering state ", state, " at ", current).AtDebug()) switch state { case StateReadyToClose: @@ -378,7 +378,7 @@ func (v *Connection) Close() error { if state.Is(StateReadyToClose, StateTerminating, StateTerminated) { return ErrClosedConnection } - log.Info("KCP|Connection: Closing connection to ", v.conn.RemoteAddr()) + log.Trace(errors.New("KCP|Connection: Closing connection to ", v.conn.RemoteAddr())) if state == StateActive { v.SetState(StateReadyToClose) @@ -455,7 +455,7 @@ func (v *Connection) Terminate() { if v == nil { return } - log.Info("KCP|Connection: Terminating connection to ", v.RemoteAddr()) + log.Trace(errors.New("KCP|Connection: Terminating connection to ", v.RemoteAddr())) //v.SetState(StateTerminated) v.OnDataInput() @@ -549,7 +549,7 @@ func (v *Connection) flush() { } if v.State() == StateTerminating { - log.Debug("KCP|Connection: #", v.conv, " sending terminating cmd.") + log.Trace(errors.New("KCP|Connection: #", v.conv, " sending terminating cmd.").AtDebug()) v.Ping(current, CommandTerminate) if current-atomic.LoadUint32(&v.stateBeginTime) > 8000 { diff --git a/transport/internet/kcp/dialer.go b/transport/internet/kcp/dialer.go index 0c9b13b0d..40a2cbef6 100644 --- a/transport/internet/kcp/dialer.go +++ b/transport/internet/kcp/dialer.go @@ -111,7 +111,7 @@ func (o *ClientConnection) Run() { func DialKCP(ctx context.Context, dest v2net.Destination) (internet.Connection, error) { dest.Network = v2net.Network_UDP - log.Info("KCP|Dialer: Dialing KCP to ", dest) + log.Trace(errors.New("KCP|Dialer: Dialing KCP to ", dest)) src := internet.DialerSourceFromContext(ctx) id := internal.NewConnectionID(src, dest) @@ -119,7 +119,7 @@ func DialKCP(ctx context.Context, dest v2net.Destination) (internet.Connection, if conn == nil { rawConn, err := internet.DialSystem(ctx, src, dest) if err != nil { - log.Error("KCP|Dialer: Failed to dial to dest: ", err) + log.Trace(errors.New("KCP|Dialer: Failed to dial to dest: ", err).AtError()) return nil, err } c := &ClientConnection{ diff --git a/transport/internet/kcp/listener.go b/transport/internet/kcp/listener.go index c1bd4187b..339cb5227 100644 --- a/transport/internet/kcp/listener.go +++ b/transport/internet/kcp/listener.go @@ -130,7 +130,7 @@ func NewListener(ctx context.Context, address v2net.Address, port v2net.Port, co l.Lock() l.hub = hub l.Unlock() - log.Info("KCP|Listener: listening on ", address, ":", port) + log.Trace(errors.New("KCP|Listener: listening on ", address, ":", port)) return l, nil } @@ -139,7 +139,7 @@ func (v *Listener) OnReceive(payload *buf.Buffer, src v2net.Destination, origina segments := v.reader.Read(payload.Bytes()) if len(segments) == 0 { - log.Info("KCP|Listener: discarding invalid payload from ", src) + log.Trace(errors.New("KCP|Listener: discarding invalid payload from ", src)) return } diff --git a/transport/internet/tcp/dialer.go b/transport/internet/tcp/dialer.go index 7af3cf149..de9f823c8 100644 --- a/transport/internet/tcp/dialer.go +++ b/transport/internet/tcp/dialer.go @@ -19,7 +19,7 @@ var ( ) func Dial(ctx context.Context, dest v2net.Destination) (internet.Connection, error) { - log.Info("Internet|TCP: Dailing TCP to ", dest) + log.Trace(errors.New("Internet|TCP: Dailing TCP to ", dest)) src := internet.DialerSourceFromContext(ctx) tcpSettings := internet.TransportSettingsFromContext(ctx).(*Config) diff --git a/transport/internet/tcp/hub.go b/transport/internet/tcp/hub.go index 62f7dd6e1..43ec711bf 100644 --- a/transport/internet/tcp/hub.go +++ b/transport/internet/tcp/hub.go @@ -37,7 +37,7 @@ func ListenTCP(ctx context.Context, address v2net.Address, port v2net.Port, conn if err != nil { return nil, err } - log.Info("TCP|Listener: Listening on ", address, ":", port) + log.Trace(errors.New("TCP|Listener: Listening on ", address, ":", port)) networkSettings := internet.TransportSettingsFromContext(ctx) tcpSettings := networkSettings.(*Config) @@ -85,7 +85,7 @@ func (v *TCPListener) KeepAccepting() { return nil }) if err != nil { - log.Warning("TCP|Listener: Failed to accepted raw connections: ", err) + log.Trace(errors.New("TCP|Listener: Failed to accepted raw connections: ", err).AtWarning()) continue } diff --git a/transport/internet/tcp/sockopt_linux.go b/transport/internet/tcp/sockopt_linux.go index 0b8149ae2..a24dd83db 100644 --- a/transport/internet/tcp/sockopt_linux.go +++ b/transport/internet/tcp/sockopt_linux.go @@ -15,18 +15,18 @@ const SO_ORIGINAL_DST = 80 func GetOriginalDestination(conn internet.Connection) net.Destination { tcpConn, ok := conn.(internet.SysFd) if !ok { - log.Info("Dokodemo: Failed to get sys fd.") + log.Trace(errors.New("Dokodemo: Failed to get sys fd.")) return net.Destination{} } fd, err := tcpConn.SysFd() if err != nil { - log.Info("Dokodemo: Failed to get original destination: ", err) + log.Trace(errors.New("Dokodemo: Failed to get original destination: ", err)) return net.Destination{} } addr, err := syscall.GetsockoptIPv6Mreq(fd, syscall.IPPROTO_IP, SO_ORIGINAL_DST) if err != nil { - log.Info("Dokodemo: Failed to call getsockopt: ", err) + log.Trace(errors.New("Dokodemo: Failed to call getsockopt: ", err)) return net.Destination{} } ip := net.IPAddress(addr.Multiaddr[4:8]) diff --git a/transport/internet/tls/config.go b/transport/internet/tls/config.go index 982d45121..34b226196 100644 --- a/transport/internet/tls/config.go +++ b/transport/internet/tls/config.go @@ -4,6 +4,7 @@ import ( "crypto/tls" "v2ray.com/core/app/log" + "v2ray.com/core/common/errors" ) var ( @@ -15,7 +16,7 @@ func (v *Config) BuildCertificates() []tls.Certificate { for _, entry := range v.Certificate { keyPair, err := tls.X509KeyPair(entry.Certificate, entry.Key) if err != nil { - log.Warning("TLS: ignoring invalid X509 key pair: ", err) + log.Trace(errors.New("TLS: ignoring invalid X509 key pair").Base(err).AtWarning()) continue } certs = append(certs, keyPair) diff --git a/transport/internet/udp/dispatcher.go b/transport/internet/udp/dispatcher.go index f526d52f2..485a63ffe 100644 --- a/transport/internet/udp/dispatcher.go +++ b/transport/internet/udp/dispatcher.go @@ -7,6 +7,7 @@ import ( "v2ray.com/core/app/dispatcher" "v2ray.com/core/app/log" "v2ray.com/core/common/buf" + "v2ray.com/core/common/errors" v2net "v2ray.com/core/common/net" "v2ray.com/core/transport/ray" ) @@ -44,7 +45,7 @@ func (v *Dispatcher) getInboundRay(ctx context.Context, dest v2net.Destination) return entry, true } - log.Info("UDP|Server: establishing new connection for ", dest) + log.Trace(errors.New("UDP|Server: establishing new connection for ", dest)) inboundRay, _ := v.dispatcher.Dispatch(ctx, dest) v.conns[dest] = inboundRay return inboundRay, false @@ -52,7 +53,7 @@ func (v *Dispatcher) getInboundRay(ctx context.Context, dest v2net.Destination) func (v *Dispatcher) Dispatch(ctx context.Context, destination v2net.Destination, payload *buf.Buffer, callback ResponseCallback) { // TODO: Add user to destString - log.Debug("UDP|Server: Dispatch request: ", destination) + log.Trace(errors.New("UDP|Server: Dispatch request: ", destination).AtDebug()) inboundRay, existing := v.getInboundRay(ctx, destination) outputStream := inboundRay.InboundInput() diff --git a/transport/internet/udp/hub.go b/transport/internet/udp/hub.go index 292e0f456..4155d9fbe 100644 --- a/transport/internet/udp/hub.go +++ b/transport/internet/udp/hub.go @@ -93,7 +93,7 @@ func ListenUDP(address v2net.Address, port v2net.Port, option ListenOption) (*Hu if err != nil { return nil, err } - log.Info("UDP|Hub: Listening on ", address, ":", port) + log.Trace(errors.New("UDP|Hub: Listening on ", address, ":", port)) if option.ReceiveOriginalDest { fd, err := internal.GetSysFd(udpConn) if err != nil { @@ -148,7 +148,7 @@ L: }) if err != nil { - log.Info("UDP|Hub: Failed to read UDP msg: ", err) + log.Trace(errors.New("UDP|Hub: Failed to read UDP msg: ", err)) buffer.Release() continue } diff --git a/transport/internet/websocket/dialer.go b/transport/internet/websocket/dialer.go index 4aed9431d..db8617e10 100644 --- a/transport/internet/websocket/dialer.go +++ b/transport/internet/websocket/dialer.go @@ -19,7 +19,7 @@ var ( ) func Dial(ctx context.Context, dest v2net.Destination) (internet.Connection, error) { - log.Info("WebSocket|Dialer: Creating connection to ", dest) + log.Trace(errors.New("WebSocket|Dialer: Creating connection to ", dest)) src := internet.DialerSourceFromContext(ctx) wsSettings := internet.TransportSettingsFromContext(ctx).(*Config) diff --git a/transport/internet/websocket/hub.go b/transport/internet/websocket/hub.go index 707cd9046..49b4d0052 100644 --- a/transport/internet/websocket/hub.go +++ b/transport/internet/websocket/hub.go @@ -35,7 +35,7 @@ func (h *requestHandler) ServeHTTP(writer http.ResponseWriter, request *http.Req } conn, err := converttovws(writer, request) if err != nil { - log.Info("WebSocket|Listener: Failed to convert to WebSocket connection: ", err) + log.Trace(errors.New("WebSocket|Listener: Failed to convert to WebSocket connection: ", err)) return }