From 43ba7bd338493787abc672e6f1017805838b77a3 Mon Sep 17 00:00:00 2001 From: fatedier Date: Tue, 12 Mar 2024 13:58:53 +0800 Subject: [PATCH] use new log package (#4054) --- client/admin_api.go | 38 ++++++------ client/connector.go | 6 +- client/control.go | 26 ++++----- client/health/health.go | 8 +-- client/proxy/proxy.go | 18 +++--- client/proxy/proxy_manager.go | 4 +- client/proxy/proxy_wrapper.go | 12 ++-- client/proxy/sudp.go | 22 +++---- client/proxy/udp.go | 20 +++---- client/proxy/xtcp.go | 34 +++++------ client/service.go | 14 ++--- client/visitor/stcp.go | 14 ++--- client/visitor/sudp.go | 32 +++++----- client/visitor/visitor_manager.go | 12 ++-- client/visitor/xtcp.go | 48 +++++++-------- cmd/frpc/sub/root.go | 6 +- cmd/frps/root.go | 8 +-- go.mod | 7 +-- go.sum | 18 +++--- pkg/metrics/mem/server.go | 4 +- pkg/nathole/controller.go | 22 +++---- pkg/nathole/nathole.go | 24 ++++---- pkg/plugin/server/manager.go | 12 ++-- pkg/ssh/gateway.go | 4 +- pkg/ssh/server.go | 6 +- pkg/util/log/log.go | 91 +++++++++++++---------------- pkg/util/vhost/http.go | 14 ++--- pkg/util/vhost/resource.go | 4 +- pkg/util/vhost/vhost.go | 16 ++--- pkg/util/xlog/xlog.go | 20 +++---- server/control.go | 34 +++++------ server/dashboard_api.go | 30 +++++----- server/proxy/http.go | 8 +-- server/proxy/https.go | 4 +- server/proxy/proxy.go | 26 ++++----- server/proxy/stcp.go | 2 +- server/proxy/sudp.go | 2 +- server/proxy/tcp.go | 4 +- server/proxy/tcpmux.go | 2 +- server/proxy/udp.go | 26 ++++----- server/proxy/xtcp.go | 2 +- server/service.go | 52 ++++++++--------- test/e2e/e2e.go | 2 +- test/e2e/e2e_test.go | 2 +- test/e2e/framework/process.go | 4 +- test/e2e/framework/request.go | 6 +- test/e2e/legacy/features/monitor.go | 2 +- test/e2e/legacy/features/real_ip.go | 8 +-- test/e2e/pkg/plugin/plugin.go | 4 +- test/e2e/v1/features/monitor.go | 2 +- test/e2e/v1/features/real_ip.go | 8 +-- 51 files changed, 389 insertions(+), 405 deletions(-) diff --git a/client/admin_api.go b/client/admin_api.go index e15fc4a4..ff889d52 100644 --- a/client/admin_api.go +++ b/client/admin_api.go @@ -76,9 +76,9 @@ func (svr *Service) apiReload(w http.ResponseWriter, r *http.Request) { strictConfigMode, _ = strconv.ParseBool(strictStr) } - log.Info("api request [/api/reload]") + log.Infof("api request [/api/reload]") defer func() { - log.Info("api response [/api/reload], code [%d]", res.Code) + log.Infof("api response [/api/reload], code [%d]", res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) @@ -89,32 +89,32 @@ func (svr *Service) apiReload(w http.ResponseWriter, r *http.Request) { if err != nil { res.Code = 400 res.Msg = err.Error() - log.Warn("reload frpc proxy config error: %s", res.Msg) + log.Warnf("reload frpc proxy config error: %s", res.Msg) return } if _, err := validation.ValidateAllClientConfig(cliCfg, proxyCfgs, visitorCfgs); err != nil { res.Code = 400 res.Msg = err.Error() - log.Warn("reload frpc proxy config error: %s", res.Msg) + log.Warnf("reload frpc proxy config error: %s", res.Msg) return } if err := svr.UpdateAllConfigurer(proxyCfgs, visitorCfgs); err != nil { res.Code = 500 res.Msg = err.Error() - log.Warn("reload frpc proxy config error: %s", res.Msg) + log.Warnf("reload frpc proxy config error: %s", res.Msg) return } - log.Info("success reload conf") + log.Infof("success reload conf") } // POST /api/stop func (svr *Service) apiStop(w http.ResponseWriter, _ *http.Request) { res := GeneralResponse{Code: 200} - log.Info("api request [/api/stop]") + log.Infof("api request [/api/stop]") defer func() { - log.Info("api response [/api/stop], code [%d]", res.Code) + log.Infof("api response [/api/stop], code [%d]", res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) @@ -165,9 +165,9 @@ func (svr *Service) apiStatus(w http.ResponseWriter, _ *http.Request) { res StatusResp = make(map[string][]ProxyStatusResp) ) - log.Info("Http request [/api/status]") + log.Infof("Http request [/api/status]") defer func() { - log.Info("Http response [/api/status]") + log.Infof("Http response [/api/status]") buf, _ = json.Marshal(&res) _, _ = w.Write(buf) }() @@ -198,9 +198,9 @@ func (svr *Service) apiStatus(w http.ResponseWriter, _ *http.Request) { func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) { res := GeneralResponse{Code: 200} - log.Info("Http get request [/api/config]") + log.Infof("Http get request [/api/config]") defer func() { - log.Info("Http get response [/api/config], code [%d]", res.Code) + log.Infof("Http get response [/api/config], code [%d]", res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) @@ -210,7 +210,7 @@ func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) { if svr.configFilePath == "" { res.Code = 400 res.Msg = "frpc has no config file path" - log.Warn("%s", res.Msg) + log.Warnf("%s", res.Msg) return } @@ -218,7 +218,7 @@ func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) { if err != nil { res.Code = 400 res.Msg = err.Error() - log.Warn("load frpc config file error: %s", res.Msg) + log.Warnf("load frpc config file error: %s", res.Msg) return } res.Msg = string(content) @@ -228,9 +228,9 @@ func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) { func (svr *Service) apiPutConfig(w http.ResponseWriter, r *http.Request) { res := GeneralResponse{Code: 200} - log.Info("Http put request [/api/config]") + log.Infof("Http put request [/api/config]") defer func() { - log.Info("Http put response [/api/config], code [%d]", res.Code) + log.Infof("Http put response [/api/config], code [%d]", res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) @@ -242,21 +242,21 @@ func (svr *Service) apiPutConfig(w http.ResponseWriter, r *http.Request) { if err != nil { res.Code = 400 res.Msg = fmt.Sprintf("read request body error: %v", err) - log.Warn("%s", res.Msg) + log.Warnf("%s", res.Msg) return } if len(body) == 0 { res.Code = 400 res.Msg = "body can't be empty" - log.Warn("%s", res.Msg) + log.Warnf("%s", res.Msg) return } if err := os.WriteFile(svr.configFilePath, body, 0o644); err != nil { res.Code = 500 res.Msg = fmt.Sprintf("write content to frpc config file error: %v", err) - log.Warn("%s", res.Msg) + log.Warnf("%s", res.Msg) return } } diff --git a/client/connector.go b/client/connector.go index 8c3cd1ec..184194a1 100644 --- a/client/connector.go +++ b/client/connector.go @@ -84,7 +84,7 @@ func (c *defaultConnectorImpl) Open() error { tlsConfig, err = transport.NewClientTLSConfig("", "", "", sn) } if err != nil { - xl.Warn("fail to build tls configuration, err: %v", err) + xl.Warnf("fail to build tls configuration, err: %v", err) return err } tlsConfig.NextProtos = []string{"frp"} @@ -164,14 +164,14 @@ func (c *defaultConnectorImpl) realConnect() (net.Conn, error) { c.cfg.Transport.TLS.TrustedCaFile, sn) if err != nil { - xl.Warn("fail to build tls configuration, err: %v", err) + xl.Warnf("fail to build tls configuration, err: %v", err) return nil, err } } proxyType, addr, auth, err := libdial.ParseProxyURL(c.cfg.Transport.ProxyURL) if err != nil { - xl.Error("fail to parse proxy url") + xl.Errorf("fail to parse proxy url") return nil, err } dialOptions := []libdial.DialOption{} diff --git a/client/control.go b/client/control.go index b272ee06..e1916890 100644 --- a/client/control.go +++ b/client/control.go @@ -124,7 +124,7 @@ func (ctl *Control) handleReqWorkConn(_ msg.Message) { xl := ctl.xl workConn, err := ctl.connectServer() if err != nil { - xl.Warn("start new connection to server error: %v", err) + xl.Warnf("start new connection to server error: %v", err) return } @@ -132,24 +132,24 @@ func (ctl *Control) handleReqWorkConn(_ msg.Message) { RunID: ctl.sessionCtx.RunID, } if err = ctl.sessionCtx.AuthSetter.SetNewWorkConn(m); err != nil { - xl.Warn("error during NewWorkConn authentication: %v", err) + xl.Warnf("error during NewWorkConn authentication: %v", err) workConn.Close() return } if err = msg.WriteMsg(workConn, m); err != nil { - xl.Warn("work connection write to server error: %v", err) + xl.Warnf("work connection write to server error: %v", err) workConn.Close() return } var startMsg msg.StartWorkConn if err = msg.ReadMsgInto(workConn, &startMsg); err != nil { - xl.Trace("work connection closed before response StartWorkConn message: %v", err) + xl.Tracef("work connection closed before response StartWorkConn message: %v", err) workConn.Close() return } if startMsg.Error != "" { - xl.Error("StartWorkConn contains error: %s", startMsg.Error) + xl.Errorf("StartWorkConn contains error: %s", startMsg.Error) workConn.Close() return } @@ -165,9 +165,9 @@ func (ctl *Control) handleNewProxyResp(m msg.Message) { // Start a new proxy handler if no error got err := ctl.pm.StartProxy(inMsg.ProxyName, inMsg.RemoteAddr, inMsg.Error) if err != nil { - xl.Warn("[%s] start error: %v", inMsg.ProxyName, err) + xl.Warnf("[%s] start error: %v", inMsg.ProxyName, err) } else { - xl.Info("[%s] start proxy success", inMsg.ProxyName) + xl.Infof("[%s] start proxy success", inMsg.ProxyName) } } @@ -178,7 +178,7 @@ func (ctl *Control) handleNatHoleResp(m msg.Message) { // Dispatch the NatHoleResp message to the related proxy. ok := ctl.msgTransporter.DispatchWithType(inMsg, msg.TypeNameNatHoleResp, inMsg.TransactionID) if !ok { - xl.Trace("dispatch NatHoleResp message to related proxy error") + xl.Tracef("dispatch NatHoleResp message to related proxy error") } } @@ -187,12 +187,12 @@ func (ctl *Control) handlePong(m msg.Message) { inMsg := m.(*msg.Pong) if inMsg.Error != "" { - xl.Error("Pong message contains error: %s", inMsg.Error) + xl.Errorf("Pong message contains error: %s", inMsg.Error) ctl.closeSession() return } ctl.lastPong.Store(time.Now()) - xl.Debug("receive heartbeat from server") + xl.Debugf("receive heartbeat from server") } // closeSession closes the control connection. @@ -241,10 +241,10 @@ func (ctl *Control) heartbeatWorker() { if ctl.sessionCtx.Common.Transport.HeartbeatInterval > 0 { // send heartbeat to server sendHeartBeat := func() (bool, error) { - xl.Debug("send heartbeat to server") + xl.Debugf("send heartbeat to server") pingMsg := &msg.Ping{} if err := ctl.sessionCtx.AuthSetter.SetPing(pingMsg); err != nil { - xl.Warn("error during ping authentication: %v, skip sending ping message", err) + xl.Warnf("error during ping authentication: %v, skip sending ping message", err) return false, err } _ = ctl.msgDispatcher.Send(pingMsg) @@ -269,7 +269,7 @@ func (ctl *Control) heartbeatWorker() { go wait.Until(func() { if time.Since(ctl.lastPong.Load().(time.Time)) > time.Duration(ctl.sessionCtx.Common.Transport.HeartbeatTimeout)*time.Second { - xl.Warn("heartbeat timeout") + xl.Warnf("heartbeat timeout") ctl.closeSession() return } diff --git a/client/health/health.go b/client/health/health.go index 63eec721..7147f779 100644 --- a/client/health/health.go +++ b/client/health/health.go @@ -112,17 +112,17 @@ func (monitor *Monitor) checkWorker() { } if err == nil { - xl.Trace("do one health check success") + xl.Tracef("do one health check success") if !monitor.statusOK && monitor.statusNormalFn != nil { - xl.Info("health check status change to success") + xl.Infof("health check status change to success") monitor.statusOK = true monitor.statusNormalFn() } } else { - xl.Warn("do one health check failed: %v", err) + xl.Warnf("do one health check failed: %v", err) monitor.failedTimes++ if monitor.statusOK && int(monitor.failedTimes) >= monitor.maxFailedTimes && monitor.statusFailedFn != nil { - xl.Warn("health check status change to failed") + xl.Warnf("health check status change to failed") monitor.statusOK = false monitor.statusFailedFn() } diff --git a/client/proxy/proxy.go b/client/proxy/proxy.go index 396539c0..f806c8f9 100644 --- a/client/proxy/proxy.go +++ b/client/proxy/proxy.go @@ -141,13 +141,13 @@ func (pxy *BaseProxy) HandleTCPWorkConnection(workConn net.Conn, m *msg.StartWor }) } - xl.Trace("handle tcp work connection, useEncryption: %t, useCompression: %t", + xl.Tracef("handle tcp work connection, useEncryption: %t, useCompression: %t", baseCfg.Transport.UseEncryption, baseCfg.Transport.UseCompression) if baseCfg.Transport.UseEncryption { remote, err = libio.WithEncryption(remote, encKey) if err != nil { workConn.Close() - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } @@ -189,9 +189,9 @@ func (pxy *BaseProxy) HandleTCPWorkConnection(workConn net.Conn, m *msg.StartWor if pxy.proxyPlugin != nil { // if plugin is set, let plugin handle connection first - xl.Debug("handle by plugin: %s", pxy.proxyPlugin.Name()) + xl.Debugf("handle by plugin: %s", pxy.proxyPlugin.Name()) pxy.proxyPlugin.Handle(remote, workConn, &extraInfo) - xl.Debug("handle by plugin finished") + xl.Debugf("handle by plugin finished") return } @@ -201,25 +201,25 @@ func (pxy *BaseProxy) HandleTCPWorkConnection(workConn net.Conn, m *msg.StartWor ) if err != nil { workConn.Close() - xl.Error("connect to local service [%s:%d] error: %v", baseCfg.LocalIP, baseCfg.LocalPort, err) + xl.Errorf("connect to local service [%s:%d] error: %v", baseCfg.LocalIP, baseCfg.LocalPort, err) return } - xl.Debug("join connections, localConn(l[%s] r[%s]) workConn(l[%s] r[%s])", localConn.LocalAddr().String(), + xl.Debugf("join connections, localConn(l[%s] r[%s]) workConn(l[%s] r[%s])", localConn.LocalAddr().String(), localConn.RemoteAddr().String(), workConn.LocalAddr().String(), workConn.RemoteAddr().String()) if extraInfo.ProxyProtocolHeader != nil { if _, err := extraInfo.ProxyProtocolHeader.WriteTo(localConn); err != nil { workConn.Close() - xl.Error("write proxy protocol header to local conn error: %v", err) + xl.Errorf("write proxy protocol header to local conn error: %v", err) return } } _, _, errs := libio.Join(localConn, remote) - xl.Debug("join connections closed") + xl.Debugf("join connections closed") if len(errs) > 0 { - xl.Trace("join connections errors: %v", errs) + xl.Tracef("join connections errors: %v", errs) } if compressionResourceRecycleFn != nil { compressionResourceRecycleFn() diff --git a/client/proxy/proxy_manager.go b/client/proxy/proxy_manager.go index 12e2f6cf..95778ce0 100644 --- a/client/proxy/proxy_manager.go +++ b/client/proxy/proxy_manager.go @@ -152,7 +152,7 @@ func (pm *Manager) UpdateAll(proxyCfgs []v1.ProxyConfigurer) { } } if len(delPxyNames) > 0 { - xl.Info("proxy removed: %s", delPxyNames) + xl.Infof("proxy removed: %s", delPxyNames) } addPxyNames := make([]string, 0) @@ -170,6 +170,6 @@ func (pm *Manager) UpdateAll(proxyCfgs []v1.ProxyConfigurer) { } } if len(addPxyNames) > 0 { - xl.Info("proxy added: %s", addPxyNames) + xl.Infof("proxy added: %s", addPxyNames) } } diff --git a/client/proxy/proxy_wrapper.go b/client/proxy/proxy_wrapper.go index 84f24abb..487e3702 100644 --- a/client/proxy/proxy_wrapper.go +++ b/client/proxy/proxy_wrapper.go @@ -114,7 +114,7 @@ func NewWrapper( addr := net.JoinHostPort(baseInfo.LocalIP, strconv.Itoa(baseInfo.LocalPort)) pw.monitor = health.NewMonitor(pw.ctx, baseInfo.HealthCheck, addr, pw.statusNormalCallback, pw.statusFailedCallback) - xl.Trace("enable health check monitor") + xl.Tracef("enable health check monitor") } pw.pxy = NewProxy(pw.ctx, pw.Cfg, clientCfg, pw.msgTransporter) @@ -197,7 +197,7 @@ func (pw *Wrapper) checkWorker() { (pw.Phase == ProxyPhaseWaitStart && now.After(pw.lastSendStartMsg.Add(waitResponseTimeout))) || (pw.Phase == ProxyPhaseStartErr && now.After(pw.lastStartErr.Add(startErrTimeout))) { - xl.Trace("change status from [%s] to [%s]", pw.Phase, ProxyPhaseWaitStart) + xl.Tracef("change status from [%s] to [%s]", pw.Phase, ProxyPhaseWaitStart) pw.Phase = ProxyPhaseWaitStart var newProxyMsg msg.NewProxy @@ -212,7 +212,7 @@ func (pw *Wrapper) checkWorker() { pw.mu.Lock() if pw.Phase == ProxyPhaseRunning || pw.Phase == ProxyPhaseWaitStart { pw.close() - xl.Trace("change status from [%s] to [%s]", pw.Phase, ProxyPhaseCheckFailed) + xl.Tracef("change status from [%s] to [%s]", pw.Phase, ProxyPhaseCheckFailed) pw.Phase = ProxyPhaseCheckFailed } pw.mu.Unlock() @@ -236,7 +236,7 @@ func (pw *Wrapper) statusNormalCallback() { default: } }) - xl.Info("health check success") + xl.Infof("health check success") } func (pw *Wrapper) statusFailedCallback() { @@ -248,7 +248,7 @@ func (pw *Wrapper) statusFailedCallback() { default: } }) - xl.Info("health check failed") + xl.Infof("health check failed") } func (pw *Wrapper) InWorkConn(workConn net.Conn, m *msg.StartWorkConn) { @@ -257,7 +257,7 @@ func (pw *Wrapper) InWorkConn(workConn net.Conn, m *msg.StartWorkConn) { pxy := pw.pxy pw.mu.RUnlock() if pxy != nil && pw.Phase == ProxyPhaseRunning { - xl.Debug("start a new work connection, localAddr: %s remoteAddr: %s", workConn.LocalAddr().String(), workConn.RemoteAddr().String()) + xl.Debugf("start a new work connection, localAddr: %s remoteAddr: %s", workConn.LocalAddr().String(), workConn.RemoteAddr().String()) go pxy.InWorkConn(workConn, m) } else { workConn.Close() diff --git a/client/proxy/sudp.go b/client/proxy/sudp.go index 4d06170d..ad9db89a 100644 --- a/client/proxy/sudp.go +++ b/client/proxy/sudp.go @@ -81,7 +81,7 @@ func (pxy *SUDPProxy) Close() { func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { xl := pxy.xl - xl.Info("incoming a new work connection for sudp proxy, %s", conn.RemoteAddr().String()) + xl.Infof("incoming a new work connection for sudp proxy, %s", conn.RemoteAddr().String()) var rwc io.ReadWriteCloser = conn var err error @@ -94,7 +94,7 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { rwc, err = libio.WithEncryption(rwc, []byte(pxy.clientCfg.Auth.Token)) if err != nil { conn.Close() - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } @@ -133,21 +133,21 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { // first to check sudp proxy is closed or not select { case <-pxy.closeCh: - xl.Trace("frpc sudp proxy is closed") + xl.Tracef("frpc sudp proxy is closed") return default: } var udpMsg msg.UDPPacket if errRet := msg.ReadMsgInto(conn, &udpMsg); errRet != nil { - xl.Warn("read from workConn for sudp error: %v", errRet) + xl.Warnf("read from workConn for sudp error: %v", errRet) return } if errRet := errors.PanicToError(func() { readCh <- &udpMsg }); errRet != nil { - xl.Warn("reader goroutine for sudp work connection closed: %v", errRet) + xl.Warnf("reader goroutine for sudp work connection closed: %v", errRet) return } } @@ -157,21 +157,21 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) { defer func() { closeFn() - xl.Info("writer goroutine for sudp work connection closed") + xl.Infof("writer goroutine for sudp work connection closed") }() var errRet error for rawMsg := range sendCh { switch m := rawMsg.(type) { case *msg.UDPPacket: - xl.Trace("frpc send udp package to frpc visitor, [udp local: %v, remote: %v], [tcp work conn local: %v, remote: %v]", + xl.Tracef("frpc send udp package to frpc visitor, [udp local: %v, remote: %v], [tcp work conn local: %v, remote: %v]", m.LocalAddr.String(), m.RemoteAddr.String(), conn.LocalAddr().String(), conn.RemoteAddr().String()) case *msg.Ping: - xl.Trace("frpc send ping message to frpc visitor") + xl.Tracef("frpc send ping message to frpc visitor") } if errRet = msg.WriteMsg(conn, rawMsg); errRet != nil { - xl.Error("sudp work write error: %v", errRet) + xl.Errorf("sudp work write error: %v", errRet) return } } @@ -191,11 +191,11 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { if errRet = errors.PanicToError(func() { sendCh <- &msg.Ping{} }); errRet != nil { - xl.Warn("heartbeat goroutine for sudp work connection closed") + xl.Warnf("heartbeat goroutine for sudp work connection closed") return } case <-pxy.closeCh: - xl.Trace("frpc sudp proxy is closed") + xl.Tracef("frpc sudp proxy is closed") return } } diff --git a/client/proxy/udp.go b/client/proxy/udp.go index 38d14ff5..b08fe160 100644 --- a/client/proxy/udp.go +++ b/client/proxy/udp.go @@ -90,7 +90,7 @@ func (pxy *UDPProxy) Close() { func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { xl := pxy.xl - xl.Info("incoming a new work connection for udp proxy, %s", conn.RemoteAddr().String()) + xl.Infof("incoming a new work connection for udp proxy, %s", conn.RemoteAddr().String()) // close resources related with old workConn pxy.Close() @@ -105,7 +105,7 @@ func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { rwc, err = libio.WithEncryption(rwc, []byte(pxy.clientCfg.Auth.Token)) if err != nil { conn.Close() - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } @@ -125,32 +125,32 @@ func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { for { var udpMsg msg.UDPPacket if errRet := msg.ReadMsgInto(conn, &udpMsg); errRet != nil { - xl.Warn("read from workConn for udp error: %v", errRet) + xl.Warnf("read from workConn for udp error: %v", errRet) return } if errRet := errors.PanicToError(func() { - xl.Trace("get udp package from workConn: %s", udpMsg.Content) + xl.Tracef("get udp package from workConn: %s", udpMsg.Content) readCh <- &udpMsg }); errRet != nil { - xl.Info("reader goroutine for udp work connection closed: %v", errRet) + xl.Infof("reader goroutine for udp work connection closed: %v", errRet) return } } } workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) { defer func() { - xl.Info("writer goroutine for udp work connection closed") + xl.Infof("writer goroutine for udp work connection closed") }() var errRet error for rawMsg := range sendCh { switch m := rawMsg.(type) { case *msg.UDPPacket: - xl.Trace("send udp package to workConn: %s", m.Content) + xl.Tracef("send udp package to workConn: %s", m.Content) case *msg.Ping: - xl.Trace("send ping message to udp workConn") + xl.Tracef("send ping message to udp workConn") } if errRet = msg.WriteMsg(conn, rawMsg); errRet != nil { - xl.Error("udp work write error: %v", errRet) + xl.Errorf("udp work write error: %v", errRet) return } } @@ -162,7 +162,7 @@ func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { if errRet = errors.PanicToError(func() { sendCh <- &msg.Ping{} }); errRet != nil { - xl.Trace("heartbeat goroutine for udp work connection closed") + xl.Tracef("heartbeat goroutine for udp work connection closed") break } } diff --git a/client/proxy/xtcp.go b/client/proxy/xtcp.go index e5e5d47e..31f9ac89 100644 --- a/client/proxy/xtcp.go +++ b/client/proxy/xtcp.go @@ -59,17 +59,17 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC var natHoleSidMsg msg.NatHoleSid err := msg.ReadMsgInto(conn, &natHoleSidMsg) if err != nil { - xl.Error("xtcp read from workConn error: %v", err) + xl.Errorf("xtcp read from workConn error: %v", err) return } - xl.Trace("nathole prepare start") + xl.Tracef("nathole prepare start") prepareResult, err := nathole.Prepare([]string{pxy.clientCfg.NatHoleSTUNServer}) if err != nil { - xl.Warn("nathole prepare error: %v", err) + xl.Warnf("nathole prepare error: %v", err) return } - xl.Info("nathole prepare success, nat type: %s, behavior: %s, addresses: %v, assistedAddresses: %v", + xl.Infof("nathole prepare success, nat type: %s, behavior: %s, addresses: %v, assistedAddresses: %v", prepareResult.NatType, prepareResult.Behavior, prepareResult.Addrs, prepareResult.AssistedAddrs) defer prepareResult.ListenConn.Close() @@ -83,14 +83,14 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC AssistedAddrs: prepareResult.AssistedAddrs, } - xl.Trace("nathole exchange info start") + xl.Tracef("nathole exchange info start") natHoleRespMsg, err := nathole.ExchangeInfo(pxy.ctx, pxy.msgTransporter, transactionID, natHoleClientMsg, 5*time.Second) if err != nil { - xl.Warn("nathole exchange info error: %v", err) + xl.Warnf("nathole exchange info error: %v", err) return } - xl.Info("get natHoleRespMsg, sid [%s], protocol [%s], candidate address %v, assisted address %v, detectBehavior: %+v", + xl.Infof("get natHoleRespMsg, sid [%s], protocol [%s], candidate address %v, assisted address %v, detectBehavior: %+v", natHoleRespMsg.Sid, natHoleRespMsg.Protocol, natHoleRespMsg.CandidateAddrs, natHoleRespMsg.AssistedAddrs, natHoleRespMsg.DetectBehavior) @@ -98,7 +98,7 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC newListenConn, raddr, err := nathole.MakeHole(pxy.ctx, listenConn, natHoleRespMsg, []byte(pxy.cfg.Secretkey)) if err != nil { listenConn.Close() - xl.Warn("make hole error: %v", err) + xl.Warnf("make hole error: %v", err) _ = pxy.msgTransporter.Send(&msg.NatHoleReport{ Sid: natHoleRespMsg.Sid, Success: false, @@ -106,7 +106,7 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC return } listenConn = newListenConn - xl.Info("establishing nat hole connection successful, sid [%s], remoteAddr [%s]", natHoleRespMsg.Sid, raddr) + xl.Infof("establishing nat hole connection successful, sid [%s], remoteAddr [%s]", natHoleRespMsg.Sid, raddr) _ = pxy.msgTransporter.Send(&msg.NatHoleReport{ Sid: natHoleRespMsg.Sid, @@ -128,14 +128,14 @@ func (pxy *XTCPProxy) listenByKCP(listenConn *net.UDPConn, raddr *net.UDPAddr, s laddr, _ := net.ResolveUDPAddr("udp", listenConn.LocalAddr().String()) lConn, err := net.DialUDP("udp", laddr, raddr) if err != nil { - xl.Warn("dial udp error: %v", err) + xl.Warnf("dial udp error: %v", err) return } defer lConn.Close() remote, err := netpkg.NewKCPConnFromUDP(lConn, true, raddr.String()) if err != nil { - xl.Warn("create kcp connection from udp connection error: %v", err) + xl.Warnf("create kcp connection from udp connection error: %v", err) return } @@ -145,7 +145,7 @@ func (pxy *XTCPProxy) listenByKCP(listenConn *net.UDPConn, raddr *net.UDPAddr, s fmuxCfg.LogOutput = io.Discard session, err := fmux.Server(remote, fmuxCfg) if err != nil { - xl.Error("create mux session error: %v", err) + xl.Errorf("create mux session error: %v", err) return } defer session.Close() @@ -153,7 +153,7 @@ func (pxy *XTCPProxy) listenByKCP(listenConn *net.UDPConn, raddr *net.UDPAddr, s for { muxConn, err := session.Accept() if err != nil { - xl.Error("accept connection error: %v", err) + xl.Errorf("accept connection error: %v", err) return } go pxy.HandleTCPWorkConnection(muxConn, startWorkConnMsg, []byte(pxy.cfg.Secretkey)) @@ -166,7 +166,7 @@ func (pxy *XTCPProxy) listenByQUIC(listenConn *net.UDPConn, _ *net.UDPAddr, star tlsConfig, err := transport.NewServerTLSConfig("", "", "") if err != nil { - xl.Warn("create tls config error: %v", err) + xl.Warnf("create tls config error: %v", err) return } tlsConfig.NextProtos = []string{"frp"} @@ -178,19 +178,19 @@ func (pxy *XTCPProxy) listenByQUIC(listenConn *net.UDPConn, _ *net.UDPAddr, star }, ) if err != nil { - xl.Warn("dial quic error: %v", err) + xl.Warnf("dial quic error: %v", err) return } // only accept one connection from raddr c, err := quicListener.Accept(pxy.ctx) if err != nil { - xl.Error("quic accept connection error: %v", err) + xl.Errorf("quic accept connection error: %v", err) return } for { stream, err := c.AcceptStream(pxy.ctx) if err != nil { - xl.Debug("quic accept stream error: %v", err) + xl.Debugf("quic accept stream error: %v", err) _ = c.CloseWithError(0, "") return } diff --git a/client/service.go b/client/service.go index 3d1a21b0..25e108fc 100644 --- a/client/service.go +++ b/client/service.go @@ -174,9 +174,9 @@ func (svr *Service) Run(ctx context.Context) error { if svr.webServer != nil { go func() { - log.Info("admin server listen on %s", svr.webServer.Address()) + log.Infof("admin server listen on %s", svr.webServer.Address()) if err := svr.webServer.Run(); err != nil { - log.Warn("admin server exit with error: %v", err) + log.Warnf("admin server exit with error: %v", err) } }() } @@ -269,14 +269,14 @@ func (svr *Service) login() (conn net.Conn, connector Connector, err error) { if loginRespMsg.Error != "" { err = fmt.Errorf("%s", loginRespMsg.Error) - xl.Error("%s", loginRespMsg.Error) + xl.Errorf("%s", loginRespMsg.Error) return } svr.runID = loginRespMsg.RunID xl.AddPrefix(xlog.LogPrefix{Name: "runID", Value: svr.runID}) - xl.Info("login to server success, get run id [%s]", loginRespMsg.RunID) + xl.Infof("login to server success, get run id [%s]", loginRespMsg.RunID) return } @@ -284,10 +284,10 @@ func (svr *Service) loopLoginUntilSuccess(maxInterval time.Duration, firstLoginE xl := xlog.FromContextSafe(svr.ctx) loginFunc := func() (bool, error) { - xl.Info("try to connect to server...") + xl.Infof("try to connect to server...") conn, connector, err := svr.login() if err != nil { - xl.Warn("connect to server error: %v", err) + xl.Warnf("connect to server error: %v", err) if firstLoginExit { svr.cancel(cancelErr{Err: err}) } @@ -313,7 +313,7 @@ func (svr *Service) loopLoginUntilSuccess(maxInterval time.Duration, firstLoginE ctl, err := NewControl(svr.ctx, sessionCtx) if err != nil { conn.Close() - xl.Error("NewControl error: %v", err) + xl.Errorf("NewControl error: %v", err) return false, err } ctl.SetInWorkConnCallback(svr.handleWorkConnCb) diff --git a/client/visitor/stcp.go b/client/visitor/stcp.go index 58433879..b26faf52 100644 --- a/client/visitor/stcp.go +++ b/client/visitor/stcp.go @@ -56,7 +56,7 @@ func (sv *STCPVisitor) worker() { for { conn, err := sv.l.Accept() if err != nil { - xl.Warn("stcp local listener closed") + xl.Warnf("stcp local listener closed") return } go sv.handleConn(conn) @@ -68,7 +68,7 @@ func (sv *STCPVisitor) internalConnWorker() { for { conn, err := sv.internalLn.Accept() if err != nil { - xl.Warn("stcp internal listener closed") + xl.Warnf("stcp internal listener closed") return } go sv.handleConn(conn) @@ -79,7 +79,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) { xl := xlog.FromContextSafe(sv.ctx) defer userConn.Close() - xl.Debug("get a new stcp user connection") + xl.Debugf("get a new stcp user connection") visitorConn, err := sv.helper.ConnectServer() if err != nil { return @@ -97,7 +97,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) { } err = msg.WriteMsg(visitorConn, newVisitorConnMsg) if err != nil { - xl.Warn("send newVisitorConnMsg to server error: %v", err) + xl.Warnf("send newVisitorConnMsg to server error: %v", err) return } @@ -105,13 +105,13 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) { _ = visitorConn.SetReadDeadline(time.Now().Add(10 * time.Second)) err = msg.ReadMsgInto(visitorConn, &newVisitorConnRespMsg) if err != nil { - xl.Warn("get newVisitorConnRespMsg error: %v", err) + xl.Warnf("get newVisitorConnRespMsg error: %v", err) return } _ = visitorConn.SetReadDeadline(time.Time{}) if newVisitorConnRespMsg.Error != "" { - xl.Warn("start new visitor connection error: %s", newVisitorConnRespMsg.Error) + xl.Warnf("start new visitor connection error: %s", newVisitorConnRespMsg.Error) return } @@ -120,7 +120,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) { if sv.cfg.Transport.UseEncryption { remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } diff --git a/client/visitor/sudp.go b/client/visitor/sudp.go index 1d489bec..284aee10 100644 --- a/client/visitor/sudp.go +++ b/client/visitor/sudp.go @@ -62,7 +62,7 @@ func (sv *SUDPVisitor) Run() (err error) { sv.sendCh = make(chan *msg.UDPPacket, 1024) sv.readCh = make(chan *msg.UDPPacket, 1024) - xl.Info("sudp start to work, listen on %s", addr) + xl.Infof("sudp start to work, listen on %s", addr) go sv.dispatcher() go udp.ForwardUserConn(sv.udpConn, sv.readCh, sv.sendCh, int(sv.clientCfg.UDPPacketSize)) @@ -84,17 +84,17 @@ func (sv *SUDPVisitor) dispatcher() { select { case firstPacket = <-sv.sendCh: if firstPacket == nil { - xl.Info("frpc sudp visitor proxy is closed") + xl.Infof("frpc sudp visitor proxy is closed") return } case <-sv.checkCloseCh: - xl.Info("frpc sudp visitor proxy is closed") + xl.Infof("frpc sudp visitor proxy is closed") return } visitorConn, err = sv.getNewVisitorConn() if err != nil { - xl.Warn("newVisitorConn to frps error: %v, try to reconnect", err) + xl.Warnf("newVisitorConn to frps error: %v, try to reconnect", err) continue } @@ -111,7 +111,7 @@ func (sv *SUDPVisitor) dispatcher() { func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) { xl := xlog.FromContextSafe(sv.ctx) - xl.Debug("starting sudp proxy worker") + xl.Debugf("starting sudp proxy worker") wg := &sync.WaitGroup{} wg.Add(2) @@ -134,21 +134,21 @@ func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) { // frpc will send heartbeat in workConn to frpc visitor for keeping alive _ = conn.SetReadDeadline(time.Now().Add(60 * time.Second)) if rawMsg, errRet = msg.ReadMsg(conn); errRet != nil { - xl.Warn("read from workconn for user udp conn error: %v", errRet) + xl.Warnf("read from workconn for user udp conn error: %v", errRet) return } _ = conn.SetReadDeadline(time.Time{}) switch m := rawMsg.(type) { case *msg.Ping: - xl.Debug("frpc visitor get ping message from frpc") + xl.Debugf("frpc visitor get ping message from frpc") continue case *msg.UDPPacket: if errRet := errors.PanicToError(func() { sv.readCh <- m - xl.Trace("frpc visitor get udp packet from workConn: %s", m.Content) + xl.Tracef("frpc visitor get udp packet from workConn: %s", m.Content) }); errRet != nil { - xl.Info("reader goroutine for udp work connection closed") + xl.Infof("reader goroutine for udp work connection closed") return } } @@ -165,25 +165,25 @@ func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) { var errRet error if firstPacket != nil { if errRet = msg.WriteMsg(conn, firstPacket); errRet != nil { - xl.Warn("sender goroutine for udp work connection closed: %v", errRet) + xl.Warnf("sender goroutine for udp work connection closed: %v", errRet) return } - xl.Trace("send udp package to workConn: %s", firstPacket.Content) + xl.Tracef("send udp package to workConn: %s", firstPacket.Content) } for { select { case udpMsg, ok := <-sv.sendCh: if !ok { - xl.Info("sender goroutine for udp work connection closed") + xl.Infof("sender goroutine for udp work connection closed") return } if errRet = msg.WriteMsg(conn, udpMsg); errRet != nil { - xl.Warn("sender goroutine for udp work connection closed: %v", errRet) + xl.Warnf("sender goroutine for udp work connection closed: %v", errRet) return } - xl.Trace("send udp package to workConn: %s", udpMsg.Content) + xl.Tracef("send udp package to workConn: %s", udpMsg.Content) case <-closeCh: return } @@ -194,7 +194,7 @@ func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) { go workConnSenderFn(workConn) wg.Wait() - xl.Info("sudp worker is closed") + xl.Infof("sudp worker is closed") } func (sv *SUDPVisitor) getNewVisitorConn() (net.Conn, error) { @@ -235,7 +235,7 @@ func (sv *SUDPVisitor) getNewVisitorConn() (net.Conn, error) { if sv.cfg.Transport.UseEncryption { remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return nil, err } } diff --git a/client/visitor/visitor_manager.go b/client/visitor/visitor_manager.go index 4f31f270..6ff65dab 100644 --- a/client/visitor/visitor_manager.go +++ b/client/visitor/visitor_manager.go @@ -79,14 +79,14 @@ func (vm *Manager) keepVisitorsRunning() { for { select { case <-vm.stopCh: - xl.Trace("gracefully shutdown visitor manager") + xl.Tracef("gracefully shutdown visitor manager") return case <-ticker.C: vm.mu.Lock() for _, cfg := range vm.cfgs { name := cfg.GetBaseConfig().Name if _, exist := vm.visitors[name]; !exist { - xl.Info("try to start visitor [%s]", name) + xl.Infof("try to start visitor [%s]", name) _ = vm.startVisitor(cfg) } } @@ -115,10 +115,10 @@ func (vm *Manager) startVisitor(cfg v1.VisitorConfigurer) (err error) { visitor := NewVisitor(vm.ctx, cfg, vm.clientCfg, vm.helper) err = visitor.Run() if err != nil { - xl.Warn("start error: %v", err) + xl.Warnf("start error: %v", err) } else { vm.visitors[name] = visitor - xl.Info("start visitor success") + xl.Infof("start visitor success") } return } @@ -156,7 +156,7 @@ func (vm *Manager) UpdateAll(cfgs []v1.VisitorConfigurer) { } } if len(delNames) > 0 { - xl.Info("visitor removed: %v", delNames) + xl.Infof("visitor removed: %v", delNames) } addNames := make([]string, 0) @@ -169,7 +169,7 @@ func (vm *Manager) UpdateAll(cfgs []v1.VisitorConfigurer) { } } if len(addNames) > 0 { - xl.Info("visitor added: %v", addNames) + xl.Infof("visitor added: %v", addNames) } } diff --git a/client/visitor/xtcp.go b/client/visitor/xtcp.go index ad773503..a1efd72b 100644 --- a/client/visitor/xtcp.go +++ b/client/visitor/xtcp.go @@ -93,7 +93,7 @@ func (sv *XTCPVisitor) worker() { for { conn, err := sv.l.Accept() if err != nil { - xl.Warn("xtcp local listener closed") + xl.Warnf("xtcp local listener closed") return } go sv.handleConn(conn) @@ -105,7 +105,7 @@ func (sv *XTCPVisitor) internalConnWorker() { for { conn, err := sv.internalLn.Accept() if err != nil { - xl.Warn("xtcp internal listener closed") + xl.Warnf("xtcp internal listener closed") return } go sv.handleConn(conn) @@ -140,14 +140,14 @@ func (sv *XTCPVisitor) keepTunnelOpenWorker() { case <-sv.ctx.Done(): return case <-ticker.C: - xl.Debug("keepTunnelOpenWorker try to check tunnel...") + xl.Debugf("keepTunnelOpenWorker try to check tunnel...") conn, err := sv.getTunnelConn() if err != nil { - xl.Warn("keepTunnelOpenWorker get tunnel connection error: %v", err) + xl.Warnf("keepTunnelOpenWorker get tunnel connection error: %v", err) _ = sv.retryLimiter.Wait(sv.ctx) continue } - xl.Debug("keepTunnelOpenWorker check success") + xl.Debugf("keepTunnelOpenWorker check success") if conn != nil { conn.Close() } @@ -164,7 +164,7 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) { } }() - xl.Debug("get a new xtcp user connection") + xl.Debugf("get a new xtcp user connection") // Open a tunnel connection to the server. If there is already a successful hole-punching connection, // it will be reused. Otherwise, it will block and wait for a successful hole-punching connection until timeout. @@ -176,15 +176,15 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) { } tunnelConn, err := sv.openTunnel(ctx) if err != nil { - xl.Error("open tunnel error: %v", err) + xl.Errorf("open tunnel error: %v", err) // no fallback, just return if sv.cfg.FallbackTo == "" { return } - xl.Debug("try to transfer connection to visitor: %s", sv.cfg.FallbackTo) + xl.Debugf("try to transfer connection to visitor: %s", sv.cfg.FallbackTo) if err := sv.helper.TransferConn(sv.cfg.FallbackTo, userConn); err != nil { - xl.Error("transfer connection to visitor %s error: %v", sv.cfg.FallbackTo, err) + xl.Errorf("transfer connection to visitor %s error: %v", sv.cfg.FallbackTo, err) return } isConnTrasfered = true @@ -195,7 +195,7 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) { if sv.cfg.Transport.UseEncryption { muxConnRWCloser, err = libio.WithEncryption(muxConnRWCloser, []byte(sv.cfg.SecretKey)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } @@ -206,9 +206,9 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) { } _, _, errs := libio.Join(userConn, muxConnRWCloser) - xl.Debug("join connections closed") + xl.Debugf("join connections closed") if len(errs) > 0 { - xl.Trace("join connections errors: %v", errs) + xl.Tracef("join connections errors: %v", errs) } } @@ -239,7 +239,7 @@ func (sv *XTCPVisitor) openTunnel(ctx context.Context) (conn net.Conn, err error if err != nil { if err != ErrNoTunnelSession { - xl.Warn("get tunnel connection error: %v", err) + xl.Warnf("get tunnel connection error: %v", err) } continue } @@ -268,19 +268,19 @@ func (sv *XTCPVisitor) getTunnelConn() (net.Conn, error) { // 4. Create a tunnel session using an underlying UDP connection. func (sv *XTCPVisitor) makeNatHole() { xl := xlog.FromContextSafe(sv.ctx) - xl.Trace("makeNatHole start") + xl.Tracef("makeNatHole start") if err := nathole.PreCheck(sv.ctx, sv.helper.MsgTransporter(), sv.cfg.ServerName, 5*time.Second); err != nil { - xl.Warn("nathole precheck error: %v", err) + xl.Warnf("nathole precheck error: %v", err) return } - xl.Trace("nathole prepare start") + xl.Tracef("nathole prepare start") prepareResult, err := nathole.Prepare([]string{sv.clientCfg.NatHoleSTUNServer}) if err != nil { - xl.Warn("nathole prepare error: %v", err) + xl.Warnf("nathole prepare error: %v", err) return } - xl.Info("nathole prepare success, nat type: %s, behavior: %s, addresses: %v, assistedAddresses: %v", + xl.Infof("nathole prepare success, nat type: %s, behavior: %s, addresses: %v, assistedAddresses: %v", prepareResult.NatType, prepareResult.Behavior, prepareResult.Addrs, prepareResult.AssistedAddrs) listenConn := prepareResult.ListenConn @@ -298,30 +298,30 @@ func (sv *XTCPVisitor) makeNatHole() { AssistedAddrs: prepareResult.AssistedAddrs, } - xl.Trace("nathole exchange info start") + xl.Tracef("nathole exchange info start") natHoleRespMsg, err := nathole.ExchangeInfo(sv.ctx, sv.helper.MsgTransporter(), transactionID, natHoleVisitorMsg, 5*time.Second) if err != nil { listenConn.Close() - xl.Warn("nathole exchange info error: %v", err) + xl.Warnf("nathole exchange info error: %v", err) return } - xl.Info("get natHoleRespMsg, sid [%s], protocol [%s], candidate address %v, assisted address %v, detectBehavior: %+v", + xl.Infof("get natHoleRespMsg, sid [%s], protocol [%s], candidate address %v, assisted address %v, detectBehavior: %+v", natHoleRespMsg.Sid, natHoleRespMsg.Protocol, natHoleRespMsg.CandidateAddrs, natHoleRespMsg.AssistedAddrs, natHoleRespMsg.DetectBehavior) newListenConn, raddr, err := nathole.MakeHole(sv.ctx, listenConn, natHoleRespMsg, []byte(sv.cfg.SecretKey)) if err != nil { listenConn.Close() - xl.Warn("make hole error: %v", err) + xl.Warnf("make hole error: %v", err) return } listenConn = newListenConn - xl.Info("establishing nat hole connection successful, sid [%s], remoteAddr [%s]", natHoleRespMsg.Sid, raddr) + xl.Infof("establishing nat hole connection successful, sid [%s], remoteAddr [%s]", natHoleRespMsg.Sid, raddr) if err := sv.session.Init(listenConn, raddr); err != nil { listenConn.Close() - xl.Warn("init tunnel session error: %v", err) + xl.Warnf("init tunnel session error: %v", err) return } } diff --git a/cmd/frpc/sub/root.go b/cmd/frpc/sub/root.go index 64cac22f..a496d077 100644 --- a/cmd/frpc/sub/root.go +++ b/cmd/frpc/sub/root.go @@ -136,11 +136,11 @@ func startService( visitorCfgs []v1.VisitorConfigurer, cfgFile string, ) error { - log.InitLog(cfg.Log.To, cfg.Log.Level, cfg.Log.MaxDays, cfg.Log.DisablePrintColor) + log.InitLogger(cfg.Log.To, cfg.Log.Level, int(cfg.Log.MaxDays), cfg.Log.DisablePrintColor) if cfgFile != "" { - log.Info("start frpc service for config file [%s]", cfgFile) - defer log.Info("frpc service for config file [%s] stopped", cfgFile) + log.Infof("start frpc service for config file [%s]", cfgFile) + defer log.Infof("frpc service for config file [%s] stopped", cfgFile) } svr, err := client.NewService(client.ServiceOptions{ Common: cfg, diff --git a/cmd/frps/root.go b/cmd/frps/root.go index cc083518..d69df5f5 100644 --- a/cmd/frps/root.go +++ b/cmd/frps/root.go @@ -99,19 +99,19 @@ func Execute() { } func runServer(cfg *v1.ServerConfig) (err error) { - log.InitLog(cfg.Log.To, cfg.Log.Level, cfg.Log.MaxDays, cfg.Log.DisablePrintColor) + log.InitLogger(cfg.Log.To, cfg.Log.Level, int(cfg.Log.MaxDays), cfg.Log.DisablePrintColor) if cfgFile != "" { - log.Info("frps uses config file: %s", cfgFile) + log.Infof("frps uses config file: %s", cfgFile) } else { - log.Info("frps uses command line arguments for config") + log.Infof("frps uses command line arguments for config") } svr, err := server.NewService(cfg) if err != nil { return err } - log.Info("frps started successfully") + log.Infof("frps started successfully") svr.Run(context.Background()) return } diff --git a/go.mod b/go.mod index f35dcfee..3d82efe4 100644 --- a/go.mod +++ b/go.mod @@ -5,8 +5,7 @@ go 1.22 require ( github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5 github.com/coreos/go-oidc/v3 v3.6.0 - github.com/fatedier/beego v0.0.0-20171024143340-6c6a4f5bd5eb - github.com/fatedier/golib v0.3.0 + github.com/fatedier/golib v0.4.0 github.com/google/uuid v1.3.0 github.com/gorilla/mux v1.8.0 github.com/gorilla/websocket v1.5.0 @@ -25,7 +24,7 @@ require ( github.com/stretchr/testify v1.8.4 github.com/tidwall/gjson v1.17.1 github.com/xtaci/kcp-go/v5 v5.6.7 - golang.org/x/crypto v0.17.0 + golang.org/x/crypto v0.18.0 golang.org/x/net v0.19.0 golang.org/x/oauth2 v0.10.0 golang.org/x/sync v0.3.0 @@ -70,7 +69,7 @@ require ( go.uber.org/mock v0.3.0 // indirect golang.org/x/exp v0.0.0-20221205204356-47842c84f3db // indirect golang.org/x/mod v0.11.0 // indirect - golang.org/x/sys v0.15.0 // indirect + golang.org/x/sys v0.16.0 // indirect golang.org/x/text v0.14.0 // indirect golang.org/x/tools v0.9.3 // indirect google.golang.org/appengine v1.6.7 // indirect diff --git a/go.sum b/go.sum index 2112c712..474da7b4 100644 --- a/go.sum +++ b/go.sum @@ -24,10 +24,8 @@ github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSs github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= github.com/envoyproxy/go-control-plane v0.9.4/go.mod h1:6rpuAdCZL397s3pYoYcLgu1mIlRU8Am5FuJP05cCM98= github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c= -github.com/fatedier/beego v0.0.0-20171024143340-6c6a4f5bd5eb h1:wCrNShQidLmvVWn/0PikGmpdP0vtQmnvyRg3ZBEhczw= -github.com/fatedier/beego v0.0.0-20171024143340-6c6a4f5bd5eb/go.mod h1:wx3gB6dbIfBRcucp94PI9Bt3I0F2c/MyNEWuhzpWiwk= -github.com/fatedier/golib v0.3.0 h1:xX0QQoYD1ns3IHVDTSysg6gL8buZvGaLyQFvBnWIRF4= -github.com/fatedier/golib v0.3.0/go.mod h1:pmX4FYyp6N4awxDB6jAgIDVOUWuH+QkVP4v30O+iJDM= +github.com/fatedier/golib v0.4.0 h1:lafvYRMhFmqrfIUChKy/f5AXqs1eDSk+GAUtLexN5bU= +github.com/fatedier/golib v0.4.0/go.mod h1:gpu+1vXxtJ072NYaNsn/YWgojDL8Ap2kFZQtbzT2qkg= github.com/fatedier/yamux v0.0.0-20230628132301-7aca4898904d h1:ynk1ra0RUqDWQfvFi5KtMiSobkVQ3cNc0ODb8CfIETo= github.com/fatedier/yamux v0.0.0-20230628132301-7aca4898904d/go.mod h1:CtWFDAQgb7dxtzFs4tWbplKIe2jSi3+5vKbgIO0SLnQ= github.com/go-jose/go-jose/v3 v3.0.1 h1:pWmKFVtt+Jl0vBZTIpz/eAKwsm6LkIxDVVbFHKkchhA= @@ -164,8 +162,8 @@ golang.org/x/crypto v0.0.0-20201012173705-84dcc777aaee/go.mod h1:LzIPMQfyMNhhGPh golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= golang.org/x/crypto v0.8.0/go.mod h1:mRqEX+O9/h5TFCrQhkgjo2yKi0yYA+9ecGkdQoHrywE= golang.org/x/crypto v0.12.0/go.mod h1:NF0Gs7EO5K4qLn+Ylc+fih8BSTeIjAP05siRnAh98yw= -golang.org/x/crypto v0.17.0 h1:r8bRNjWL3GshPW3gkd+RpvzWrZAwPS49OmTGZ/uhM4k= -golang.org/x/crypto v0.17.0/go.mod h1:gCAAfMLgwOJRpTjQ2zCCt2OcSfYMTeZVSRtQlPC7Nq4= +golang.org/x/crypto v0.18.0 h1:PGVlW0xEltQnzFZ55hkuX5+KLyrMYhHld1YHO4AKcdc= +golang.org/x/crypto v0.18.0/go.mod h1:R0j02AL6hcrfOiy9T4ZYp/rcWeMxM3L6QYxlOuEG1mg= golang.org/x/exp v0.0.0-20190121172915-509febef88a4/go.mod h1:CJ0aWSM057203Lf6IL+f9T1iT9GByDxfZKAQTCR3kQA= golang.org/x/exp v0.0.0-20221205204356-47842c84f3db h1:D/cFflL63o2KSLJIwjlcIt8PR064j/xsmdEJL/YvY/o= golang.org/x/exp v0.0.0-20221205204356-47842c84f3db/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= @@ -216,16 +214,16 @@ golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.7.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc= -golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= +golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU= +golang.org/x/sys v0.16.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo= golang.org/x/term v0.0.0-20210927222741-03fcf44c2211/go.mod h1:jbD1KX2456YbFQfuXm/mYQcufACuNUgVhRMnK/tPxf8= golang.org/x/term v0.5.0/go.mod h1:jMB1sMXY+tzblOD4FWmEbocvup2/aLOaQEp7JmGp78k= golang.org/x/term v0.7.0/go.mod h1:P32HKFT3hSsZrRxla30E9HqToFYAQPCMs/zFMBUFqPY= golang.org/x/term v0.8.0/go.mod h1:xPskH00ivmX89bAKVGSKKtLOWNx2+17Eiy94tnKShWo= golang.org/x/term v0.11.0/go.mod h1:zC9APTIj3jG3FdV/Ons+XE1riIZXG4aZ4GTHiPZJPIU= -golang.org/x/term v0.15.0 h1:y/Oo/a/q3IXu26lQgl04j/gjuBDOBlx7X6Om1j2CPW4= -golang.org/x/term v0.15.0/go.mod h1:BDl952bC7+uMoWR75FIrCDx79TPU9oHkTZ9yRbYOrX0= +golang.org/x/term v0.16.0 h1:m+B6fahuftsE9qjo0VWp2FW0mB3MTJvR0BaMQrq0pmE= +golang.org/x/term v0.16.0/go.mod h1:yn7UURbUtPyrVJPGPq404EukNFxcm/foM+bV/bfcDsY= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= diff --git a/pkg/metrics/mem/server.go b/pkg/metrics/mem/server.go index 4f08001b..d92546c4 100644 --- a/pkg/metrics/mem/server.go +++ b/pkg/metrics/mem/server.go @@ -62,7 +62,7 @@ func (m *serverMetrics) run() { time.Sleep(12 * time.Hour) start := time.Now() count, total := m.clearUselessInfo(time.Duration(7*24) * time.Hour) - log.Debug("clear useless proxy statistics data count %d/%d, cost %v", count, total, time.Since(start)) + log.Debugf("clear useless proxy statistics data count %d/%d, cost %v", count, total, time.Since(start)) } }() } @@ -80,7 +80,7 @@ func (m *serverMetrics) clearUselessInfo(continuousOfflineDuration time.Duration time.Since(data.LastCloseTime) > continuousOfflineDuration { delete(m.info.ProxyStatistics, name) count++ - log.Trace("clear proxy [%s]'s statistics data, lastCloseTime: [%s]", name, data.LastCloseTime.String()) + log.Tracef("clear proxy [%s]'s statistics data, lastCloseTime: [%s]", name, data.LastCloseTime.String()) } } return count, total diff --git a/pkg/nathole/controller.go b/pkg/nathole/controller.go index 9c558326..2eca5929 100644 --- a/pkg/nathole/controller.go +++ b/pkg/nathole/controller.go @@ -115,7 +115,7 @@ func (c *Controller) CleanWorker(ctx context.Context) { case <-ticker.C: start := time.Now() count, total := c.analyzer.Clean() - log.Trace("clean %d/%d nathole analysis data, cost %v", count, total, time.Since(start)) + log.Tracef("clean %d/%d nathole analysis data, cost %v", count, total, time.Since(start)) case <-ctx.Done(): return } @@ -191,11 +191,11 @@ func (c *Controller) HandleVisitor(m *msg.NatHoleVisitor, transporter transport. return nil }() if err != nil { - log.Warn("handle visitorMsg error: %v", err) + log.Warnf("handle visitorMsg error: %v", err) _ = transporter.Send(c.GenNatHoleResponse(m.TransactionID, nil, err.Error())) return } - log.Trace("handle visitor message, sid [%s], server name: %s", sid, m.ProxyName) + log.Tracef("handle visitor message, sid [%s], server name: %s", sid, m.ProxyName) defer func() { c.mu.Lock() @@ -213,14 +213,14 @@ func (c *Controller) HandleVisitor(m *msg.NatHoleVisitor, transporter transport. select { case <-session.notifyCh: case <-time.After(time.Duration(NatHoleTimeout) * time.Second): - log.Debug("wait for NatHoleClient message timeout, sid [%s]", sid) + log.Debugf("wait for NatHoleClient message timeout, sid [%s]", sid) return } // Make hole-punching decisions based on the NAT information of the client and visitor. vResp, cResp, err := c.analysis(session) if err != nil { - log.Debug("sid [%s] analysis error: %v", err) + log.Debugf("sid [%s] analysis error: %v", err) vResp = c.GenNatHoleResponse(session.visitorMsg.TransactionID, nil, err.Error()) cResp = c.GenNatHoleResponse(session.clientMsg.TransactionID, nil, err.Error()) } @@ -257,7 +257,7 @@ func (c *Controller) HandleClient(m *msg.NatHoleClient, transporter transport.Me if !ok { return } - log.Trace("handle client message, sid [%s], server name: %s", session.sid, m.ProxyName) + log.Tracef("handle client message, sid [%s], server name: %s", session.sid, m.ProxyName) session.clientMsg = m session.clientTransporter = transporter select { @@ -271,13 +271,13 @@ func (c *Controller) HandleReport(m *msg.NatHoleReport) { session, ok := c.sessions[m.Sid] c.mu.RUnlock() if !ok { - log.Trace("sid [%s] report make hole success: %v, but session not found", m.Sid, m.Success) + log.Tracef("sid [%s] report make hole success: %v, but session not found", m.Sid, m.Success) return } if m.Success { c.analyzer.ReportSuccess(session.analysisKey, session.recommandMode, session.recommandIndex) } - log.Info("sid [%s] report make hole success: %v, mode %v, index %v", + log.Infof("sid [%s] report make hole success: %v, mode %v, index %v", m.Sid, m.Success, session.recommandMode, session.recommandIndex) } @@ -359,10 +359,10 @@ func (c *Controller) analysis(session *Session) (*msg.NatHoleResp, *msg.NatHoleR }, } - log.Debug("sid [%s] visitor nat: %+v, candidateAddrs: %v; client nat: %+v, candidateAddrs: %v, protocol: %s", + log.Debugf("sid [%s] visitor nat: %+v, candidateAddrs: %v; client nat: %+v, candidateAddrs: %v, protocol: %s", session.sid, *vNatFeature, vm.MappedAddrs, *cNatFeature, cm.MappedAddrs, protocol) - log.Debug("sid [%s] visitor detect behavior: %+v", session.sid, vResp.DetectBehavior) - log.Debug("sid [%s] client detect behavior: %+v", session.sid, cResp.DetectBehavior) + log.Debugf("sid [%s] visitor detect behavior: %+v", session.sid, vResp.DetectBehavior) + log.Debugf("sid [%s] client detect behavior: %+v", session.sid, cResp.DetectBehavior) return vResp, cResp, nil } diff --git a/pkg/nathole/nathole.go b/pkg/nathole/nathole.go index 065d0eb4..18cd12bc 100644 --- a/pkg/nathole/nathole.go +++ b/pkg/nathole/nathole.go @@ -204,7 +204,7 @@ func MakeHole(ctx context.Context, listenConn *net.UDPConn, m *msg.NatHoleResp, for i := 0; i < m.DetectBehavior.ListenRandomPorts; i++ { tmpConn, err := net.ListenUDP("udp4", nil) if err != nil { - xl.Warn("listen random udp addr error: %v", err) + xl.Warnf("listen random udp addr error: %v", err) continue } listenConns = append(listenConns, tmpConn) @@ -216,7 +216,7 @@ func MakeHole(ctx context.Context, listenConn *net.UDPConn, m *msg.NatHoleResp, for _, detectAddr := range detectAddrs { for _, conn := range listenConns { if err := sendSidMessage(ctx, conn, m.Sid, transactionID, detectAddr, key, m.DetectBehavior.TTL); err != nil { - xl.Trace("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) + xl.Tracef("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) } } } @@ -289,16 +289,16 @@ func waitDetectMessage( if err != nil { return nil, err } - xl.Debug("get udp message local %s, from %s", conn.LocalAddr(), raddr) + xl.Debugf("get udp message local %s, from %s", conn.LocalAddr(), raddr) var m msg.NatHoleSid if err := DecodeMessageInto(buf[:n], key, &m); err != nil { - xl.Warn("decode sid message error: %v", err) + xl.Warnf("decode sid message error: %v", err) continue } pool.PutBuf(buf) if m.Sid != sid { - xl.Warn("get sid message with wrong sid: %s, expect: %s", m.Sid, sid) + xl.Warnf("get sid message with wrong sid: %s, expect: %s", m.Sid, sid) continue } @@ -311,7 +311,7 @@ func waitDetectMessage( m.Response = true buf2, err := EncodeMessage(&m, key) if err != nil { - xl.Warn("encode sid message error: %v", err) + xl.Warnf("encode sid message error: %v", err) continue } _, _ = conn.WriteToUDP(buf2, raddr) @@ -329,7 +329,7 @@ func sendSidMessage( if ttl > 0 { ttlStr = fmt.Sprintf(" with ttl %d", ttl) } - xl.Trace("send sid message from %s to %s%s", conn.LocalAddr(), addr, ttlStr) + xl.Tracef("send sid message from %s to %s%s", conn.LocalAddr(), addr, ttlStr) raddr, err := net.ResolveUDPAddr("udp4", addr) if err != nil { return err @@ -351,14 +351,14 @@ func sendSidMessage( uConn := ipv4.NewConn(conn) original, err := uConn.TTL() if err != nil { - xl.Trace("get ttl error %v", err) + xl.Tracef("get ttl error %v", err) return err } - xl.Trace("original ttl %d", original) + xl.Tracef("original ttl %d", original) err = uConn.SetTTL(ttl) if err != nil { - xl.Trace("set ttl error %v", err) + xl.Tracef("set ttl error %v", err) } else { defer func() { _ = uConn.SetTTL(original) @@ -382,7 +382,7 @@ func sendSidMessageToRangePorts( for i := portsRange.From; i <= portsRange.To; i++ { detectAddr := net.JoinHostPort(ip, strconv.Itoa(i)) if err := sendFunc(conn, detectAddr); err != nil { - xl.Trace("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) + xl.Tracef("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) } time.Sleep(2 * time.Millisecond) } @@ -422,7 +422,7 @@ func sendSidMessageToRandomPorts( for _, ip := range slices.Compact(parseIPs(addrs)) { detectAddr := net.JoinHostPort(ip, strconv.Itoa(port)) if err := sendFunc(conn, detectAddr); err != nil { - xl.Trace("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) + xl.Tracef("send sid message from %s to %s error: %v", conn.LocalAddr(), detectAddr, err) } time.Sleep(time.Millisecond * 15) } diff --git a/pkg/plugin/server/manager.go b/pkg/plugin/server/manager.go index 516f407e..ed96444a 100644 --- a/pkg/plugin/server/manager.go +++ b/pkg/plugin/server/manager.go @@ -86,7 +86,7 @@ func (m *Manager) Login(content *LoginContent) (*LoginContent, error) { for _, p := range m.loginPlugins { res, retContent, err = p.Handle(ctx, OpLogin, *content) if err != nil { - xl.Warn("send Login request to plugin [%s] error: %v", p.Name(), err) + xl.Warnf("send Login request to plugin [%s] error: %v", p.Name(), err) return nil, errors.New("send Login request to plugin error") } if res.Reject { @@ -120,7 +120,7 @@ func (m *Manager) NewProxy(content *NewProxyContent) (*NewProxyContent, error) { for _, p := range m.newProxyPlugins { res, retContent, err = p.Handle(ctx, OpNewProxy, *content) if err != nil { - xl.Warn("send NewProxy request to plugin [%s] error: %v", p.Name(), err) + xl.Warnf("send NewProxy request to plugin [%s] error: %v", p.Name(), err) return nil, errors.New("send NewProxy request to plugin error") } if res.Reject { @@ -147,7 +147,7 @@ func (m *Manager) CloseProxy(content *CloseProxyContent) error { for _, p := range m.closeProxyPlugins { _, _, err := p.Handle(ctx, OpCloseProxy, *content) if err != nil { - xl.Warn("send CloseProxy request to plugin [%s] error: %v", p.Name(), err) + xl.Warnf("send CloseProxy request to plugin [%s] error: %v", p.Name(), err) errs = append(errs, fmt.Sprintf("[%s]: %v", p.Name(), err)) } } @@ -179,7 +179,7 @@ func (m *Manager) Ping(content *PingContent) (*PingContent, error) { for _, p := range m.pingPlugins { res, retContent, err = p.Handle(ctx, OpPing, *content) if err != nil { - xl.Warn("send Ping request to plugin [%s] error: %v", p.Name(), err) + xl.Warnf("send Ping request to plugin [%s] error: %v", p.Name(), err) return nil, errors.New("send Ping request to plugin error") } if res.Reject { @@ -213,7 +213,7 @@ func (m *Manager) NewWorkConn(content *NewWorkConnContent) (*NewWorkConnContent, for _, p := range m.newWorkConnPlugins { res, retContent, err = p.Handle(ctx, OpNewWorkConn, *content) if err != nil { - xl.Warn("send NewWorkConn request to plugin [%s] error: %v", p.Name(), err) + xl.Warnf("send NewWorkConn request to plugin [%s] error: %v", p.Name(), err) return nil, errors.New("send NewWorkConn request to plugin error") } if res.Reject { @@ -247,7 +247,7 @@ func (m *Manager) NewUserConn(content *NewUserConnContent) (*NewUserConnContent, for _, p := range m.newUserConnPlugins { res, retContent, err = p.Handle(ctx, OpNewUserConn, *content) if err != nil { - xl.Info("send NewUserConn request to plugin [%s] error: %v", p.Name(), err) + xl.Infof("send NewUserConn request to plugin [%s] error: %v", p.Name(), err) return nil, errors.New("send NewUserConn request to plugin error") } if res.Reject { diff --git a/pkg/ssh/gateway.go b/pkg/ssh/gateway.go index 90f2228e..5716f040 100644 --- a/pkg/ssh/gateway.go +++ b/pkg/ssh/gateway.go @@ -75,7 +75,7 @@ func NewGateway( sshConfig.PublicKeyCallback = func(conn ssh.ConnMetadata, key ssh.PublicKey) (*ssh.Permissions, error) { authorizedKeysMap, err := loadAuthorizedKeysFromFile(cfg.AuthorizedKeysFile) if err != nil { - log.Error("load authorized keys file error: %v", err) + log.Errorf("load authorized keys file error: %v", err) return nil, fmt.Errorf("internal error") } @@ -120,7 +120,7 @@ func (g *Gateway) handleConn(conn net.Conn) { return } if err := ts.Run(); err != nil { - log.Error("ssh tunnel server run error: %v", err) + log.Errorf("ssh tunnel server run error: %v", err) } } diff --git a/pkg/ssh/server.go b/pkg/ssh/server.go index 7fb93c34..2adab17f 100644 --- a/pkg/ssh/server.go +++ b/pkg/ssh/server.go @@ -123,7 +123,7 @@ func (s *TunnelServer) Run() error { // join workConn and ssh channel c, err := s.openConn(addr) if err != nil { - log.Trace("open conn error: %v", err) + log.Tracef("open conn error: %v", err) workConn.Close() return false } @@ -167,7 +167,7 @@ func (s *TunnelServer) Run() error { if ps, err := s.waitProxyStatusReady(pc.GetBaseConfig().Name, time.Second); err != nil { s.writeToClient(err.Error()) - log.Warn("wait proxy status ready error: %v", err) + log.Warnf("wait proxy status ready error: %v", err) } else { // success s.writeToClient(createSuccessInfo(clientCfg.User, pc, ps)) @@ -175,7 +175,7 @@ func (s *TunnelServer) Run() error { } s.vc.Close() - log.Trace("ssh tunnel connection from %v closed", sshConn.RemoteAddr()) + log.Tracef("ssh tunnel connection from %v closed", sshConn.RemoteAddr()) s.closeDoneChOnce.Do(func() { _ = sshConn.Close() close(s.doneCh) diff --git a/pkg/util/log/log.go b/pkg/util/log/log.go index a1391b32..f6399e00 100644 --- a/pkg/util/log/log.go +++ b/pkg/util/log/log.go @@ -15,78 +15,65 @@ package log import ( - "fmt" + "os" - "github.com/fatedier/beego/logs" + "github.com/fatedier/golib/log" ) -// Log is the under log object -var Log *logs.BeeLogger +var Logger *log.Logger func init() { - Log = logs.NewLogger(200) - Log.EnableFuncCallDepth(true) - Log.SetLogFuncCallDepth(Log.GetLogFuncCallDepth() + 1) + Logger = log.New( + log.WithCaller(true), + log.AddCallerSkip(1), + log.WithLevel(log.InfoLevel), + ) } -func InitLog(logFile string, logLevel string, maxdays int64, disableLogColor bool) { - SetLogFile(logFile, maxdays, disableLogColor) - SetLogLevel(logLevel) -} - -// SetLogFile to configure log params -func SetLogFile(logFile string, maxdays int64, disableLogColor bool) { - if logFile == "console" { - params := "" - if disableLogColor { - params = `{"color": false}` +func InitLogger(logPath string, levelStr string, maxDays int, disableLogColor bool) { + options := []log.Option{} + if logPath == "console" { + if !disableLogColor { + options = append(options, + log.WithOutput(log.NewConsoleWriter(log.ConsoleConfig{ + Colorful: true, + }, os.Stdout)), + ) } - _ = Log.SetLogger("console", params) } else { - params := fmt.Sprintf(`{"filename": "%s", "maxdays": %d}`, logFile, maxdays) - _ = Log.SetLogger("file", params) + writer := log.NewRotateFileWriter(log.RotateFileConfig{ + FileName: logPath, + Mode: log.RotateFileModeDaily, + MaxDays: maxDays, + }) + writer.Init() + options = append(options, log.WithOutput(writer)) } -} -// SetLogLevel set log level, default is warning -// value: error, warning, info, debug, trace -func SetLogLevel(logLevel string) { - var level int - switch logLevel { - case "error": - level = 3 - case "warn": - level = 4 - case "info": - level = 6 - case "debug": - level = 7 - case "trace": - level = 8 - default: - level = 4 // warning + level, err := log.ParseLevel(levelStr) + if err != nil { + level = log.InfoLevel } - Log.SetLevel(level) + options = append(options, log.WithLevel(level)) + Logger = Logger.WithOptions(options...) } -// wrap log - -func Error(format string, v ...interface{}) { - Log.Error(format, v...) +func Errorf(format string, v ...interface{}) { + Logger.Errorf(format, v...) } -func Warn(format string, v ...interface{}) { - Log.Warn(format, v...) +func Warnf(format string, v ...interface{}) { + Logger.Warnf(format, v...) } -func Info(format string, v ...interface{}) { - Log.Info(format, v...) +func Infof(format string, v ...interface{}) { + Logger.Infof(format, v...) } -func Debug(format string, v ...interface{}) { - Log.Debug(format, v...) +func Debugf(format string, v ...interface{}) { + Logger.Debugf(format, v...) } -func Trace(format string, v ...interface{}) { - Log.Trace(format, v...) +func Tracef(format string, v ...interface{}) { + Logger.Tracef(format, v...) } diff --git a/pkg/util/vhost/http.go b/pkg/util/vhost/http.go index 7aa67c98..34a1400a 100644 --- a/pkg/util/vhost/http.go +++ b/pkg/util/vhost/http.go @@ -20,7 +20,7 @@ import ( "encoding/base64" "errors" "fmt" - "log" + stdlog "log" "net" "net/http" "net/http/httputil" @@ -32,7 +32,7 @@ import ( "github.com/fatedier/golib/pool" httppkg "github.com/fatedier/frp/pkg/util/http" - logpkg "github.com/fatedier/frp/pkg/util/log" + "github.com/fatedier/frp/pkg/util/log" ) var ErrNoRouteFound = errors.New("no route found") @@ -76,7 +76,7 @@ func NewHTTPReverseProxy(option HTTPReverseProxyOptions, vhostRouter *Routers) * // ignore error here, it will use CreateConnFn instead later endpoint, _ = rc.ChooseEndpointFn() reqRouteInfo.Endpoint = endpoint - logpkg.Trace("choose endpoint name [%s] for http request host [%s] path [%s] httpuser [%s]", + log.Tracef("choose endpoint name [%s] for http request host [%s] path [%s] httpuser [%s]", endpoint, oldHost, reqRouteInfo.URL, reqRouteInfo.HTTPUser) } // Set {domain}.{location}.{routeByHTTPUser}.{endpoint} as URL host here to let http transport reuse connections. @@ -116,9 +116,9 @@ func NewHTTPReverseProxy(option HTTPReverseProxyOptions, vhostRouter *Routers) * }, }, BufferPool: newWrapPool(), - ErrorLog: log.New(newWrapLogger(), "", 0), + ErrorLog: stdlog.New(newWrapLogger(), "", 0), ErrorHandler: func(rw http.ResponseWriter, req *http.Request, err error) { - logpkg.Warn("do http proxy request [host: %s] error: %v", req.Host, err) + log.Warnf("do http proxy request [host: %s] error: %v", req.Host, err) rw.WriteHeader(http.StatusNotFound) _, _ = rw.Write(getNotFoundPageContent()) }, @@ -145,7 +145,7 @@ func (rp *HTTPReverseProxy) UnRegister(routeCfg RouteConfig) { func (rp *HTTPReverseProxy) GetRouteConfig(domain, location, routeByHTTPUser string) *RouteConfig { vr, ok := rp.getVhost(domain, location, routeByHTTPUser) if ok { - logpkg.Debug("get new HTTP request host [%s] path [%s] httpuser [%s]", domain, location, routeByHTTPUser) + log.Debugf("get new HTTP request host [%s] path [%s] httpuser [%s]", domain, location, routeByHTTPUser) return vr.payload.(*RouteConfig) } return nil @@ -335,6 +335,6 @@ type wrapLogger struct{} func newWrapLogger() *wrapLogger { return &wrapLogger{} } func (l *wrapLogger) Write(p []byte) (n int, err error) { - logpkg.Warn("%s", string(bytes.TrimRight(p, "\n"))) + log.Warnf("%s", string(bytes.TrimRight(p, "\n"))) return len(p), nil } diff --git a/pkg/util/vhost/resource.go b/pkg/util/vhost/resource.go index bf91e133..a65e2997 100644 --- a/pkg/util/vhost/resource.go +++ b/pkg/util/vhost/resource.go @@ -20,7 +20,7 @@ import ( "net/http" "os" - logpkg "github.com/fatedier/frp/pkg/util/log" + "github.com/fatedier/frp/pkg/util/log" "github.com/fatedier/frp/pkg/util/version" ) @@ -58,7 +58,7 @@ func getNotFoundPageContent() []byte { if NotFoundPagePath != "" { buf, err = os.ReadFile(NotFoundPagePath) if err != nil { - logpkg.Warn("read custom 404 page error: %v", err) + log.Warnf("read custom 404 page error: %v", err) buf = []byte(NotFound) } } else { diff --git a/pkg/util/vhost/vhost.go b/pkg/util/vhost/vhost.go index d529e424..b1370599 100644 --- a/pkg/util/vhost/vhost.go +++ b/pkg/util/vhost/vhost.go @@ -203,7 +203,7 @@ func (v *Muxer) handle(c net.Conn) { sConn, reqInfoMap, err := v.vhostFunc(c) if err != nil { - log.Debug("get hostname from http/https request error: %v", err) + log.Debugf("get hostname from http/https request error: %v", err) _ = c.Close() return } @@ -213,7 +213,7 @@ func (v *Muxer) handle(c net.Conn) { httpUser := reqInfoMap["HTTPUser"] l, ok := v.getListener(name, path, httpUser) if !ok { - log.Debug("http request for host [%s] path [%s] httpUser [%s] not found", name, path, httpUser) + log.Debugf("http request for host [%s] path [%s] httpUser [%s] not found", name, path, httpUser) v.failHook(sConn) return } @@ -221,7 +221,7 @@ func (v *Muxer) handle(c net.Conn) { xl := xlog.FromContextSafe(l.ctx) if v.successHook != nil { if err := v.successHook(c, reqInfoMap); err != nil { - xl.Info("success func failure on vhost connection: %v", err) + xl.Infof("success func failure on vhost connection: %v", err) _ = c.Close() return } @@ -232,7 +232,7 @@ func (v *Muxer) handle(c net.Conn) { if l.mux.checkAuth != nil && l.username != "" { ok, err := l.mux.checkAuth(c, l.username, l.password, reqInfoMap) if !ok || err != nil { - xl.Debug("auth failed for user: %s", l.username) + xl.Debugf("auth failed for user: %s", l.username) _ = c.Close() return } @@ -244,12 +244,12 @@ func (v *Muxer) handle(c net.Conn) { } c = sConn - xl.Debug("new request host [%s] path [%s] httpUser [%s]", name, path, httpUser) + xl.Debugf("new request host [%s] path [%s] httpUser [%s]", name, path, httpUser) err = errors.PanicToError(func() { l.accept <- c }) if err != nil { - xl.Warn("listener is already closed, ignore this request") + xl.Warnf("listener is already closed, ignore this request") } } @@ -278,10 +278,10 @@ func (l *Listener) Accept() (net.Conn, error) { if l.mux.rewriteHost != nil { sConn, err := l.mux.rewriteHost(conn, l.rewriteHost) if err != nil { - xl.Warn("host header rewrite failed: %v", err) + xl.Warnf("host header rewrite failed: %v", err) return nil, fmt.Errorf("host header rewrite failed") } - xl.Debug("rewrite host to [%s] success", l.rewriteHost) + xl.Debugf("rewrite host to [%s] success", l.rewriteHost) conn = sConn } return netpkg.NewContextConn(l.ctx, conn), nil diff --git a/pkg/util/xlog/xlog.go b/pkg/util/xlog/xlog.go index 56b07522..184c0c1f 100644 --- a/pkg/util/xlog/xlog.go +++ b/pkg/util/xlog/xlog.go @@ -94,22 +94,22 @@ func (l *Logger) Spawn() *Logger { return nl } -func (l *Logger) Error(format string, v ...interface{}) { - log.Log.Error(l.prefixString+format, v...) +func (l *Logger) Errorf(format string, v ...interface{}) { + log.Logger.Errorf(l.prefixString+format, v...) } -func (l *Logger) Warn(format string, v ...interface{}) { - log.Log.Warn(l.prefixString+format, v...) +func (l *Logger) Warnf(format string, v ...interface{}) { + log.Logger.Warnf(l.prefixString+format, v...) } -func (l *Logger) Info(format string, v ...interface{}) { - log.Log.Info(l.prefixString+format, v...) +func (l *Logger) Infof(format string, v ...interface{}) { + log.Logger.Infof(l.prefixString+format, v...) } -func (l *Logger) Debug(format string, v ...interface{}) { - log.Log.Debug(l.prefixString+format, v...) +func (l *Logger) Debugf(format string, v ...interface{}) { + log.Logger.Debugf(l.prefixString+format, v...) } -func (l *Logger) Trace(format string, v ...interface{}) { - log.Log.Trace(l.prefixString+format, v...) +func (l *Logger) Tracef(format string, v ...interface{}) { + log.Logger.Tracef(l.prefixString+format, v...) } diff --git a/server/control.go b/server/control.go index dbb1af0a..ea8a34c1 100644 --- a/server/control.go +++ b/server/control.go @@ -224,7 +224,7 @@ func (ctl *Control) Close() error { func (ctl *Control) Replaced(newCtl *Control) { xl := ctl.xl - xl.Info("Replaced by client [%s]", newCtl.runID) + xl.Infof("Replaced by client [%s]", newCtl.runID) ctl.runID = "" ctl.conn.Close() } @@ -233,17 +233,17 @@ func (ctl *Control) RegisterWorkConn(conn net.Conn) error { xl := ctl.xl defer func() { if err := recover(); err != nil { - xl.Error("panic error: %v", err) - xl.Error(string(debug.Stack())) + xl.Errorf("panic error: %v", err) + xl.Errorf(string(debug.Stack())) } }() select { case ctl.workConnCh <- conn: - xl.Debug("new work connection registered") + xl.Debugf("new work connection registered") return nil default: - xl.Debug("work connection pool is full, discarding") + xl.Debugf("work connection pool is full, discarding") return fmt.Errorf("work connection pool is full, discarding") } } @@ -256,8 +256,8 @@ func (ctl *Control) GetWorkConn() (workConn net.Conn, err error) { xl := ctl.xl defer func() { if err := recover(); err != nil { - xl.Error("panic error: %v", err) - xl.Error(string(debug.Stack())) + xl.Errorf("panic error: %v", err) + xl.Errorf(string(debug.Stack())) } }() @@ -269,7 +269,7 @@ func (ctl *Control) GetWorkConn() (workConn net.Conn, err error) { err = pkgerr.ErrCtlClosed return } - xl.Debug("get work connection from pool") + xl.Debugf("get work connection from pool") default: // no work connections available in the poll, send message to frpc to get more if err := ctl.msgDispatcher.Send(&msg.ReqWorkConn{}); err != nil { @@ -280,13 +280,13 @@ func (ctl *Control) GetWorkConn() (workConn net.Conn, err error) { case workConn, ok = <-ctl.workConnCh: if !ok { err = pkgerr.ErrCtlClosed - xl.Warn("no work connections available, %v", err) + xl.Warnf("no work connections available, %v", err) return } case <-time.After(time.Duration(ctl.serverCfg.UserConnTimeout) * time.Second): err = fmt.Errorf("timeout trying to get work connection") - xl.Warn("%v", err) + xl.Warnf("%v", err) return } } @@ -305,7 +305,7 @@ func (ctl *Control) heartbeatWorker() { if !lo.FromPtr(ctl.serverCfg.Transport.TCPMux) && ctl.serverCfg.Transport.HeartbeatTimeout > 0 { go wait.Until(func() { if time.Since(ctl.lastPing.Load().(time.Time)) > time.Duration(ctl.serverCfg.Transport.HeartbeatTimeout)*time.Second { - xl.Warn("heartbeat timeout") + xl.Warnf("heartbeat timeout") ctl.conn.Close() return } @@ -356,7 +356,7 @@ func (ctl *Control) worker() { } metrics.Server.CloseClient() - xl.Info("client exit success") + xl.Infof("client exit success") close(ctl.doneCh) } @@ -393,12 +393,12 @@ func (ctl *Control) handleNewProxy(m msg.Message) { ProxyName: inMsg.ProxyName, } if err != nil { - xl.Warn("new proxy [%s] type [%s] error: %v", inMsg.ProxyName, inMsg.ProxyType, err) + xl.Warnf("new proxy [%s] type [%s] error: %v", inMsg.ProxyName, inMsg.ProxyType, err) resp.Error = util.GenerateResponseErrorString(fmt.Sprintf("new proxy [%s] error", inMsg.ProxyName), err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient)) } else { resp.RemoteAddr = remoteAddr - xl.Info("new proxy [%s] type [%s] success", inMsg.ProxyName, inMsg.ProxyType) + xl.Infof("new proxy [%s] type [%s] success", inMsg.ProxyName, inMsg.ProxyType) metrics.Server.NewProxy(inMsg.ProxyName, inMsg.ProxyType) } _ = ctl.msgDispatcher.Send(resp) @@ -422,14 +422,14 @@ func (ctl *Control) handlePing(m msg.Message) { err = ctl.authVerifier.VerifyPing(inMsg) } if err != nil { - xl.Warn("received invalid ping: %v", err) + xl.Warnf("received invalid ping: %v", err) _ = ctl.msgDispatcher.Send(&msg.Pong{ Error: util.GenerateResponseErrorString("invalid ping", err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient)), }) return } ctl.lastPing.Store(time.Now()) - xl.Debug("receive heartbeat") + xl.Debugf("receive heartbeat") _ = ctl.msgDispatcher.Send(&msg.Pong{}) } @@ -452,7 +452,7 @@ func (ctl *Control) handleCloseProxy(m msg.Message) { xl := ctl.xl inMsg := m.(*msg.CloseProxy) _ = ctl.CloseProxy(inMsg) - xl.Info("close proxy [%s] success", inMsg.ProxyName) + xl.Infof("close proxy [%s] success", inMsg.ProxyName) } func (ctl *Control) RegisterProxy(pxyMsg *msg.NewProxy) (remoteAddr string, err error) { diff --git a/server/dashboard_api.go b/server/dashboard_api.go index 9ecd5a7c..62415c96 100644 --- a/server/dashboard_api.go +++ b/server/dashboard_api.go @@ -99,14 +99,14 @@ func (svr *Service) healthz(w http.ResponseWriter, _ *http.Request) { func (svr *Service) apiServerInfo(w http.ResponseWriter, r *http.Request) { res := GeneralResponse{Code: 200} defer func() { - log.Info("Http response [%s]: code [%d]", r.URL.Path, res.Code) + log.Infof("Http response [%s]: code [%d]", r.URL.Path, res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) } }() - log.Info("Http request: [%s]", r.URL.Path) + log.Infof("Http request: [%s]", r.URL.Path) serverStats := mem.StatsCollector.GetServer() svrResp := serverInfoResp{ Version: version.Full(), @@ -219,13 +219,13 @@ func (svr *Service) apiProxyByType(w http.ResponseWriter, r *http.Request) { proxyType := params["type"] defer func() { - log.Info("Http response [%s]: code [%d]", r.URL.Path, res.Code) + log.Infof("Http response [%s]: code [%d]", r.URL.Path, res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) } }() - log.Info("Http request: [%s]", r.URL.Path) + log.Infof("Http request: [%s]", r.URL.Path) proxyInfoResp := GetProxyInfoResp{} proxyInfoResp.Proxies = svr.getProxyStatsByType(proxyType) @@ -245,12 +245,12 @@ func (svr *Service) getProxyStatsByType(proxyType string) (proxyInfos []*ProxySt if pxy, ok := svr.pxyManager.GetByName(ps.Name); ok { content, err := json.Marshal(pxy.GetConfigurer()) if err != nil { - log.Warn("marshal proxy [%s] conf info error: %v", ps.Name, err) + log.Warnf("marshal proxy [%s] conf info error: %v", ps.Name, err) continue } proxyInfo.Conf = getConfByType(ps.Type) if err = json.Unmarshal(content, &proxyInfo.Conf); err != nil { - log.Warn("unmarshal proxy [%s] conf info error: %v", ps.Name, err) + log.Warnf("unmarshal proxy [%s] conf info error: %v", ps.Name, err) continue } proxyInfo.Status = "online" @@ -291,13 +291,13 @@ func (svr *Service) apiProxyByTypeAndName(w http.ResponseWriter, r *http.Request name := params["name"] defer func() { - log.Info("Http response [%s]: code [%d]", r.URL.Path, res.Code) + log.Infof("Http response [%s]: code [%d]", r.URL.Path, res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) } }() - log.Info("Http request: [%s]", r.URL.Path) + log.Infof("Http request: [%s]", r.URL.Path) var proxyStatsResp GetProxyStatsResp proxyStatsResp, res.Code, res.Msg = svr.getProxyStatsByTypeAndName(proxyType, name) @@ -319,14 +319,14 @@ func (svr *Service) getProxyStatsByTypeAndName(proxyType string, proxyName strin if pxy, ok := svr.pxyManager.GetByName(proxyName); ok { content, err := json.Marshal(pxy.GetConfigurer()) if err != nil { - log.Warn("marshal proxy [%s] conf info error: %v", ps.Name, err) + log.Warnf("marshal proxy [%s] conf info error: %v", ps.Name, err) code = 400 msg = "parse conf error" return } proxyInfo.Conf = getConfByType(ps.Type) if err = json.Unmarshal(content, &proxyInfo.Conf); err != nil { - log.Warn("unmarshal proxy [%s] conf info error: %v", ps.Name, err) + log.Warnf("unmarshal proxy [%s] conf info error: %v", ps.Name, err) code = 400 msg = "parse conf error" return @@ -359,13 +359,13 @@ func (svr *Service) apiProxyTraffic(w http.ResponseWriter, r *http.Request) { name := params["name"] defer func() { - log.Info("Http response [%s]: code [%d]", r.URL.Path, res.Code) + log.Infof("Http response [%s]: code [%d]", r.URL.Path, res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) } }() - log.Info("Http request: [%s]", r.URL.Path) + log.Infof("Http request: [%s]", r.URL.Path) trafficResp := GetProxyTrafficResp{} trafficResp.Name = name @@ -387,9 +387,9 @@ func (svr *Service) apiProxyTraffic(w http.ResponseWriter, r *http.Request) { func (svr *Service) deleteProxies(w http.ResponseWriter, r *http.Request) { res := GeneralResponse{Code: 200} - log.Info("Http request: [%s]", r.URL.Path) + log.Infof("Http request: [%s]", r.URL.Path) defer func() { - log.Info("Http response [%s]: code [%d]", r.URL.Path, res.Code) + log.Infof("Http response [%s]: code [%d]", r.URL.Path, res.Code) w.WriteHeader(res.Code) if len(res.Msg) > 0 { _, _ = w.Write([]byte(res.Msg)) @@ -403,5 +403,5 @@ func (svr *Service) deleteProxies(w http.ResponseWriter, r *http.Request) { return } cleared, total := mem.StatsCollector.ClearOfflineProxies() - log.Info("cleared [%d] offline proxies, total [%d] proxies", cleared, total) + log.Infof("cleared [%d] offline proxies, total [%d] proxies", cleared, total) } diff --git a/server/proxy/http.go b/server/proxy/http.go index 44a462b7..cd4c4b96 100644 --- a/server/proxy/http.go +++ b/server/proxy/http.go @@ -107,7 +107,7 @@ func (pxy *HTTPProxy) Run() (remoteAddr string, err error) { }) } addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPPort)) - xl.Info("http proxy listen for host [%s] location [%s] group [%s], routeByHTTPUser [%s]", + xl.Infof("http proxy listen for host [%s] location [%s] group [%s], routeByHTTPUser [%s]", routeConfig.Domain, routeConfig.Location, pxy.cfg.LoadBalancer.Group, pxy.cfg.RouteByHTTPUser) } } @@ -140,7 +140,7 @@ func (pxy *HTTPProxy) Run() (remoteAddr string, err error) { } addrs = append(addrs, util.CanonicalAddr(tmpRouteConfig.Domain, pxy.serverCfg.VhostHTTPPort)) - xl.Info("http proxy listen for host [%s] location [%s] group [%s], routeByHTTPUser [%s]", + xl.Infof("http proxy listen for host [%s] location [%s] group [%s], routeByHTTPUser [%s]", routeConfig.Domain, routeConfig.Location, pxy.cfg.LoadBalancer.Group, pxy.cfg.RouteByHTTPUser) } } @@ -152,7 +152,7 @@ func (pxy *HTTPProxy) GetRealConn(remoteAddr string) (workConn net.Conn, err err xl := pxy.xl rAddr, errRet := net.ResolveTCPAddr("tcp", remoteAddr) if errRet != nil { - xl.Warn("resolve TCP addr [%s] error: %v", remoteAddr, errRet) + xl.Warnf("resolve TCP addr [%s] error: %v", remoteAddr, errRet) // we do not return error here since remoteAddr is not necessary for proxies without proxy protocol enabled } @@ -166,7 +166,7 @@ func (pxy *HTTPProxy) GetRealConn(remoteAddr string) (workConn net.Conn, err err if pxy.cfg.Transport.UseEncryption { rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } diff --git a/server/proxy/https.go b/server/proxy/https.go index dc9b77eb..4575ac13 100644 --- a/server/proxy/https.go +++ b/server/proxy/https.go @@ -64,7 +64,7 @@ func (pxy *HTTPSProxy) Run() (remoteAddr string, err error) { err = errRet return } - xl.Info("https proxy listen for host [%s]", routeConfig.Domain) + xl.Infof("https proxy listen for host [%s]", routeConfig.Domain) pxy.listeners = append(pxy.listeners, l) addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort)) } @@ -76,7 +76,7 @@ func (pxy *HTTPSProxy) Run() (remoteAddr string, err error) { err = errRet return } - xl.Info("https proxy listen for host [%s]", routeConfig.Domain) + xl.Infof("https proxy listen for host [%s]", routeConfig.Domain) pxy.listeners = append(pxy.listeners, l) addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort)) } diff --git a/server/proxy/proxy.go b/server/proxy/proxy.go index f5c850e9..d5ab0f13 100644 --- a/server/proxy/proxy.go +++ b/server/proxy/proxy.go @@ -112,7 +112,7 @@ func (pxy *BaseProxy) GetConfigurer() v1.ProxyConfigurer { func (pxy *BaseProxy) Close() { xl := xlog.FromContextSafe(pxy.ctx) - xl.Info("proxy closing") + xl.Infof("proxy closing") for _, l := range pxy.listeners { l.Close() } @@ -125,10 +125,10 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn, // try all connections from the pool for i := 0; i < pxy.poolCount+1; i++ { if workConn, err = pxy.getWorkConnFn(); err != nil { - xl.Warn("failed to get work connection: %v", err) + xl.Warnf("failed to get work connection: %v", err) return } - xl.Debug("get a new work connection: [%s]", workConn.RemoteAddr().String()) + xl.Debugf("get a new work connection: [%s]", workConn.RemoteAddr().String()) xl.Spawn().AppendPrefix(pxy.GetName()) workConn = netpkg.NewContextConn(pxy.ctx, workConn) @@ -158,7 +158,7 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn, Error: "", }) if err != nil { - xl.Warn("failed to send message to work connection from pool: %v, times: %d", err, i) + xl.Warnf("failed to send message to work connection from pool: %v, times: %d", err, i) workConn.Close() } else { break @@ -166,7 +166,7 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn, } if err != nil { - xl.Error("try to get work connection failed in the end") + xl.Errorf("try to get work connection failed in the end") return } return @@ -193,15 +193,15 @@ func (pxy *BaseProxy) startCommonTCPListenersHandler() { if max := 1 * time.Second; tempDelay > max { tempDelay = max } - xl.Info("met temporary error: %s, sleep for %s ...", err, tempDelay) + xl.Infof("met temporary error: %s, sleep for %s ...", err, tempDelay) time.Sleep(tempDelay) continue } - xl.Warn("listener is closed: %s", err) + xl.Warnf("listener is closed: %s", err) return } - xl.Info("get a user connection [%s]", c.RemoteAddr().String()) + xl.Infof("get a user connection [%s]", c.RemoteAddr().String()) go pxy.handleUserTCPConnection(c) } }(listener) @@ -225,7 +225,7 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) { } _, err := rc.PluginManager.NewUserConn(content) if err != nil { - xl.Warn("the user conn [%s] was rejected, err:%v", content.RemoteAddr, err) + xl.Warnf("the user conn [%s] was rejected, err:%v", content.RemoteAddr, err) return } @@ -237,12 +237,12 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) { defer workConn.Close() var local io.ReadWriteCloser = workConn - xl.Trace("handler user tcp connection, use_encryption: %t, use_compression: %t", + xl.Tracef("handler user tcp connection, use_encryption: %t, use_compression: %t", cfg.Transport.UseEncryption, cfg.Transport.UseCompression) if cfg.Transport.UseEncryption { local, err = libio.WithEncryption(local, []byte(serverCfg.Auth.Token)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) return } } @@ -258,7 +258,7 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) { }) } - xl.Debug("join connections, workConn(l[%s] r[%s]) userConn(l[%s] r[%s])", workConn.LocalAddr().String(), + xl.Debugf("join connections, workConn(l[%s] r[%s]) userConn(l[%s] r[%s])", workConn.LocalAddr().String(), workConn.RemoteAddr().String(), userConn.LocalAddr().String(), userConn.RemoteAddr().String()) name := pxy.GetName() @@ -268,7 +268,7 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) { metrics.Server.CloseConnection(name, proxyType) metrics.Server.AddTrafficIn(name, proxyType, inCount) metrics.Server.AddTrafficOut(name, proxyType, outCount) - xl.Debug("join connections closed") + xl.Debugf("join connections closed") } type Options struct { diff --git a/server/proxy/stcp.go b/server/proxy/stcp.go index 4f08a7c1..06b1b17f 100644 --- a/server/proxy/stcp.go +++ b/server/proxy/stcp.go @@ -53,7 +53,7 @@ func (pxy *STCPProxy) Run() (remoteAddr string, err error) { return } pxy.listeners = append(pxy.listeners, listener) - xl.Info("stcp proxy custom listen success") + xl.Infof("stcp proxy custom listen success") pxy.startCommonTCPListenersHandler() return diff --git a/server/proxy/sudp.go b/server/proxy/sudp.go index a6d7c798..f37fb423 100644 --- a/server/proxy/sudp.go +++ b/server/proxy/sudp.go @@ -53,7 +53,7 @@ func (pxy *SUDPProxy) Run() (remoteAddr string, err error) { return } pxy.listeners = append(pxy.listeners, listener) - xl.Info("sudp proxy custom listen success") + xl.Infof("sudp proxy custom listen success") pxy.startCommonTCPListenersHandler() return diff --git a/server/proxy/tcp.go b/server/proxy/tcp.go index 4196ad4a..a6eae3a9 100644 --- a/server/proxy/tcp.go +++ b/server/proxy/tcp.go @@ -62,7 +62,7 @@ func (pxy *TCPProxy) Run() (remoteAddr string, err error) { }() pxy.realBindPort = realBindPort pxy.listeners = append(pxy.listeners, l) - xl.Info("tcp proxy listen port [%d] in group [%s]", pxy.cfg.RemotePort, pxy.cfg.LoadBalancer.Group) + xl.Infof("tcp proxy listen port [%d] in group [%s]", pxy.cfg.RemotePort, pxy.cfg.LoadBalancer.Group) } else { pxy.realBindPort, err = pxy.rc.TCPPortManager.Acquire(pxy.name, pxy.cfg.RemotePort) if err != nil { @@ -79,7 +79,7 @@ func (pxy *TCPProxy) Run() (remoteAddr string, err error) { return } pxy.listeners = append(pxy.listeners, listener) - xl.Info("tcp proxy listen port [%d]", pxy.cfg.RemotePort) + xl.Infof("tcp proxy listen port [%d]", pxy.cfg.RemotePort) } pxy.cfg.RemotePort = pxy.realBindPort diff --git a/server/proxy/tcpmux.go b/server/proxy/tcpmux.go index 5b914c39..6e95b66b 100644 --- a/server/proxy/tcpmux.go +++ b/server/proxy/tcpmux.go @@ -65,7 +65,7 @@ func (pxy *TCPMuxProxy) httpConnectListen( if err != nil { return nil, err } - pxy.xl.Info("tcpmux httpconnect multiplexer listens for host [%s], group [%s] routeByHTTPUser [%s]", + pxy.xl.Infof("tcpmux httpconnect multiplexer listens for host [%s], group [%s] routeByHTTPUser [%s]", domain, pxy.cfg.LoadBalancer.Group, pxy.cfg.RouteByHTTPUser) pxy.listeners = append(pxy.listeners, l) return append(addrs, util.CanonicalAddr(domain, pxy.serverCfg.TCPMuxHTTPConnectPort)), nil diff --git a/server/proxy/udp.go b/server/proxy/udp.go index ea970818..53a07d52 100644 --- a/server/proxy/udp.go +++ b/server/proxy/udp.go @@ -97,10 +97,10 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { udpConn, errRet := net.ListenUDP("udp", addr) if errRet != nil { err = errRet - xl.Warn("listen udp port error: %v", err) + xl.Warnf("listen udp port error: %v", err) return } - xl.Info("udp proxy listen port [%d]", pxy.cfg.RemotePort) + xl.Infof("udp proxy listen port [%d]", pxy.cfg.RemotePort) pxy.udpConn = udpConn pxy.sendCh = make(chan *msg.UDPPacket, 1024) @@ -114,11 +114,11 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { rawMsg msg.Message errRet error ) - xl.Trace("loop waiting message from udp workConn") + xl.Tracef("loop waiting message from udp workConn") // client will send heartbeat in workConn for keeping alive _ = conn.SetReadDeadline(time.Now().Add(time.Duration(60) * time.Second)) if rawMsg, errRet = msg.ReadMsg(conn); errRet != nil { - xl.Warn("read from workConn for udp error: %v", errRet) + xl.Warnf("read from workConn for udp error: %v", errRet) _ = conn.Close() // notify proxy to start a new work connection // ignore error here, it means the proxy is closed @@ -128,15 +128,15 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { return } if err := conn.SetReadDeadline(time.Time{}); err != nil { - xl.Warn("set read deadline error: %v", err) + xl.Warnf("set read deadline error: %v", err) } switch m := rawMsg.(type) { case *msg.Ping: - xl.Trace("udp work conn get ping message") + xl.Tracef("udp work conn get ping message") continue case *msg.UDPPacket: if errRet := errors.PanicToError(func() { - xl.Trace("get udp message from workConn: %s", m.Content) + xl.Tracef("get udp message from workConn: %s", m.Content) pxy.readCh <- m metrics.Server.AddTrafficOut( pxy.GetName(), @@ -145,7 +145,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { ) }); errRet != nil { conn.Close() - xl.Info("reader goroutine for udp work connection closed") + xl.Infof("reader goroutine for udp work connection closed") return } } @@ -159,15 +159,15 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { select { case udpMsg, ok := <-pxy.sendCh: if !ok { - xl.Info("sender goroutine for udp work connection closed") + xl.Infof("sender goroutine for udp work connection closed") return } if errRet = msg.WriteMsg(conn, udpMsg); errRet != nil { - xl.Info("sender goroutine for udp work connection closed: %v", errRet) + xl.Infof("sender goroutine for udp work connection closed: %v", errRet) conn.Close() return } - xl.Trace("send message to udp workConn: %s", udpMsg.Content) + xl.Tracef("send message to udp workConn: %s", udpMsg.Content) metrics.Server.AddTrafficIn( pxy.GetName(), pxy.GetConfigurer().GetBaseConfig().Type, @@ -175,7 +175,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { ) continue case <-ctx.Done(): - xl.Info("sender goroutine for udp work connection closed") + xl.Infof("sender goroutine for udp work connection closed") return } } @@ -207,7 +207,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) { if pxy.cfg.Transport.UseEncryption { rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token)) if err != nil { - xl.Error("create encryption stream error: %v", err) + xl.Errorf("create encryption stream error: %v", err) workConn.Close() continue } diff --git a/server/proxy/xtcp.go b/server/proxy/xtcp.go index fe60c630..f69d0790 100644 --- a/server/proxy/xtcp.go +++ b/server/proxy/xtcp.go @@ -77,7 +77,7 @@ func (pxy *XTCPProxy) Run() (remoteAddr string, err error) { } errRet = msg.WriteMsg(workConn, m) if errRet != nil { - xl.Warn("write nat hole sid package error, %v", errRet) + xl.Warnf("write nat hole sid package error, %v", errRet) } workConn.Close() } diff --git a/server/service.go b/server/service.go index c2410b06..12564325 100644 --- a/server/service.go +++ b/server/service.go @@ -172,13 +172,13 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { if err != nil { return nil, fmt.Errorf("create vhost tcpMuxer error, %v", err) } - log.Info("tcpmux httpconnect multiplexer listen on %s, passthough: %v", address, cfg.TCPMuxPassthrough) + log.Infof("tcpmux httpconnect multiplexer listen on %s, passthough: %v", address, cfg.TCPMuxPassthrough) } // Init all plugins for _, p := range cfg.HTTPPlugins { svr.pluginManager.Register(plugin.NewHTTPPluginOptions(p)) - log.Info("plugin [%s] has been registered", p.Name) + log.Infof("plugin [%s] has been registered", p.Name) } svr.rc.PluginManager = svr.pluginManager @@ -222,7 +222,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { ln = svr.muxer.DefaultListener() svr.listener = ln - log.Info("frps tcp listen on %s", address) + log.Infof("frps tcp listen on %s", address) // Listen for accepting connections from client using kcp protocol. if cfg.KCPBindPort > 0 { @@ -231,7 +231,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { if err != nil { return nil, fmt.Errorf("listen on kcp udp address %s error: %v", address, err) } - log.Info("frps kcp listen on udp %s", address) + log.Infof("frps kcp listen on udp %s", address) } if cfg.QUICBindPort > 0 { @@ -246,7 +246,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { if err != nil { return nil, fmt.Errorf("listen on quic udp address %s error: %v", address, err) } - log.Info("frps quic listen on %s", address) + log.Infof("frps quic listen on %s", address) } if cfg.SSHTunnelGateway.BindPort > 0 { @@ -255,7 +255,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { return nil, fmt.Errorf("create ssh gateway error: %v", err) } svr.sshTunnelGateway = sshGateway - log.Info("frps sshTunnelGateway listen on port %d", cfg.SSHTunnelGateway.BindPort) + log.Infof("frps sshTunnelGateway listen on port %d", cfg.SSHTunnelGateway.BindPort) } // Listen for accepting connections from client using websocket protocol. @@ -289,7 +289,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { go func() { _ = server.Serve(l) }() - log.Info("http service listen on %s", address) + log.Infof("http service listen on %s", address) } // Create https vhost muxer. @@ -303,7 +303,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) { if err != nil { return nil, fmt.Errorf("create server listener error, %v", err) } - log.Info("https service listen on %s", address) + log.Infof("https service listen on %s", address) } svr.rc.VhostHTTPSMuxer, err = vhost.NewHTTPSMuxer(l, vhostReadWriteTimeout) @@ -335,9 +335,9 @@ func (svr *Service) Run(ctx context.Context) { // run dashboard web server. if svr.webServer != nil { go func() { - log.Info("dashboard listen on %s", svr.webServer.Address()) + log.Infof("dashboard listen on %s", svr.webServer.Address()) if err := svr.webServer.Run(); err != nil { - log.Warn("dashboard server exit with error: %v", err) + log.Warnf("dashboard server exit with error: %v", err) } }() } @@ -408,7 +408,7 @@ func (svr *Service) handleConnection(ctx context.Context, conn net.Conn, interna _ = conn.SetReadDeadline(time.Now().Add(connReadTimeout)) if rawMsg, err = msg.ReadMsg(conn); err != nil { - log.Trace("Failed to read message: %v", err) + log.Tracef("Failed to read message: %v", err) conn.Close() return } @@ -430,7 +430,7 @@ func (svr *Service) handleConnection(ctx context.Context, conn net.Conn, interna // If login failed, send error message there. // Otherwise send success message in control's work goroutine. if err != nil { - xl.Warn("register control error: %v", err) + xl.Warnf("register control error: %v", err) _ = msg.WriteMsg(conn, &msg.LoginResp{ Version: version.Full(), Error: util.GenerateResponseErrorString("register control error", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), @@ -443,7 +443,7 @@ func (svr *Service) handleConnection(ctx context.Context, conn net.Conn, interna } case *msg.NewVisitorConn: if err = svr.RegisterVisitorConn(conn, m); err != nil { - xl.Warn("register visitor conn error: %v", err) + xl.Warnf("register visitor conn error: %v", err) _ = msg.WriteMsg(conn, &msg.NewVisitorConnResp{ ProxyName: m.ProxyName, Error: util.GenerateResponseErrorString("register visitor conn error", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), @@ -456,7 +456,7 @@ func (svr *Service) handleConnection(ctx context.Context, conn net.Conn, interna }) } default: - log.Warn("Error message type for the new connection [%s]", conn.RemoteAddr().String()) + log.Warnf("Error message type for the new connection [%s]", conn.RemoteAddr().String()) conn.Close() } } @@ -469,7 +469,7 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) { for { c, err := l.Accept() if err != nil { - log.Warn("Listener for incoming connections from client closed") + log.Warnf("Listener for incoming connections from client closed") return } // inject xlog object into net.Conn context @@ -479,17 +479,17 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) { c = netpkg.NewContextConn(xlog.NewContext(ctx, xl), c) if !internal { - log.Trace("start check TLS connection...") + log.Tracef("start check TLS connection...") originConn := c forceTLS := svr.cfg.Transport.TLS.Force var isTLS, custom bool c, isTLS, custom, err = netpkg.CheckAndEnableTLSServerConnWithTimeout(c, svr.tlsConfig, forceTLS, connReadTimeout) if err != nil { - log.Warn("CheckAndEnableTLSServerConnWithTimeout error: %v", err) + log.Warnf("CheckAndEnableTLSServerConnWithTimeout error: %v", err) originConn.Close() continue } - log.Trace("check TLS connection success, isTLS: %v custom: %v internal: %v", isTLS, custom, internal) + log.Tracef("check TLS connection success, isTLS: %v custom: %v internal: %v", isTLS, custom, internal) } // Start a new goroutine to handle connection. @@ -501,7 +501,7 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) { fmuxCfg.MaxStreamWindowSize = 6 * 1024 * 1024 session, err := fmux.Server(frpConn, fmuxCfg) if err != nil { - log.Warn("Failed to create mux connection: %v", err) + log.Warnf("Failed to create mux connection: %v", err) frpConn.Close() return } @@ -509,7 +509,7 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) { for { stream, err := session.AcceptStream() if err != nil { - log.Debug("Accept new mux stream error: %v", err) + log.Debugf("Accept new mux stream error: %v", err) session.Close() return } @@ -527,7 +527,7 @@ func (svr *Service) HandleQUICListener(l *quic.Listener) { for { c, err := l.Accept(context.Background()) if err != nil { - log.Warn("QUICListener for incoming connections from client closed") + log.Warnf("QUICListener for incoming connections from client closed") return } // Start a new goroutine to handle connection. @@ -535,7 +535,7 @@ func (svr *Service) HandleQUICListener(l *quic.Listener) { for { stream, err := frpConn.AcceptStream(context.Background()) if err != nil { - log.Debug("Accept new quic mux stream error: %v", err) + log.Debugf("Accept new quic mux stream error: %v", err) _ = frpConn.CloseWithError(0, "") return } @@ -560,7 +560,7 @@ func (svr *Service) RegisterControl(ctlConn net.Conn, loginMsg *msg.Login, inter xl := xlog.FromContextSafe(ctx) xl.AppendPrefix(loginMsg.RunID) ctx = xlog.NewContext(ctx, xl) - xl.Info("client login info: ip [%s] version [%s] hostname [%s] os [%s] arch [%s]", + xl.Infof("client login info: ip [%s] version [%s] hostname [%s] os [%s] arch [%s]", ctlConn.RemoteAddr().String(), loginMsg.Version, loginMsg.Hostname, loginMsg.Os, loginMsg.Arch) // Check auth. @@ -575,7 +575,7 @@ func (svr *Service) RegisterControl(ctlConn net.Conn, loginMsg *msg.Login, inter // TODO(fatedier): use SessionContext ctl, err := NewControl(ctx, svr.rc, svr.pxyManager, svr.pluginManager, authVerifier, ctlConn, !internal, loginMsg, svr.cfg) if err != nil { - xl.Warn("create new controller error: %v", err) + xl.Warnf("create new controller error: %v", err) // don't return detailed errors to client return fmt.Errorf("unexpected error when creating new controller") } @@ -601,7 +601,7 @@ func (svr *Service) RegisterWorkConn(workConn net.Conn, newMsg *msg.NewWorkConn) xl := netpkg.NewLogFromConn(workConn) ctl, exist := svr.ctlManager.GetByID(newMsg.RunID) if !exist { - xl.Warn("No client control found for run id [%s]", newMsg.RunID) + xl.Warnf("No client control found for run id [%s]", newMsg.RunID) return fmt.Errorf("no client control found for run id [%s]", newMsg.RunID) } // server plugin hook @@ -620,7 +620,7 @@ func (svr *Service) RegisterWorkConn(workConn net.Conn, newMsg *msg.NewWorkConn) err = ctl.authVerifier.VerifyNewWorkConn(newMsg) } if err != nil { - xl.Warn("invalid NewWorkConn with run id [%s]", newMsg.RunID) + xl.Warnf("invalid NewWorkConn with run id [%s]", newMsg.RunID) _ = msg.WriteMsg(workConn, &msg.StartWorkConn{ Error: util.GenerateResponseErrorString("invalid NewWorkConn", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), }) diff --git a/test/e2e/e2e.go b/test/e2e/e2e.go index 30887d2a..994ac59d 100644 --- a/test/e2e/e2e.go +++ b/test/e2e/e2e.go @@ -38,7 +38,7 @@ func RunE2ETests(t *testing.T) { // Randomize specs as well as suites suiteConfig.RandomizeAllSpecs = true - log.Info("Starting e2e run %q on Ginkgo node %d of total %d", + log.Infof("Starting e2e run %q on Ginkgo node %d of total %d", framework.RunID, suiteConfig.ParallelProcess, suiteConfig.ParallelTotal) ginkgo.RunSpecs(t, "frp e2e suite", suiteConfig, reporterConfig) } diff --git a/test/e2e/e2e_test.go b/test/e2e/e2e_test.go index 27c36e0c..e32f89f0 100644 --- a/test/e2e/e2e_test.go +++ b/test/e2e/e2e_test.go @@ -34,7 +34,7 @@ func TestMain(m *testing.M) { os.Exit(1) } - log.InitLog("console", framework.TestContext.LogLevel, 0, true) + log.InitLogger("console", framework.TestContext.LogLevel, 0, true) os.Exit(m.Run()) } diff --git a/test/e2e/framework/process.go b/test/e2e/framework/process.go index ae89e820..0845914b 100644 --- a/test/e2e/framework/process.go +++ b/test/e2e/framework/process.go @@ -31,7 +31,7 @@ func (f *Framework) RunProcesses(serverTemplates []string, clientTemplates []str ExpectNoError(err) if TestContext.Debug { - flog.Debug("[%s] %s", path, outs[i]) + flog.Debugf("[%s] %s", path, outs[i]) } p := process.NewWithEnvs(TestContext.FRPServerPath, []string{"-c", path}, f.osEnvs) @@ -52,7 +52,7 @@ func (f *Framework) RunProcesses(serverTemplates []string, clientTemplates []str ExpectNoError(err) if TestContext.Debug { - flog.Debug("[%s] %s", path, outs[index]) + flog.Debugf("[%s] %s", path, outs[index]) } p := process.NewWithEnvs(TestContext.FRPClientPath, []string{"-c", path}, f.osEnvs) diff --git a/test/e2e/framework/request.go b/test/e2e/framework/request.go index 6b75a259..53d44a3e 100644 --- a/test/e2e/framework/request.go +++ b/test/e2e/framework/request.go @@ -20,7 +20,7 @@ func ExpectResponseCode(code int) EnsureFunc { if resp.Code == code { return true } - flog.Warn("Expect code %d, but got %d", code, resp.Code) + flog.Warnf("Expect code %d, but got %d", code, resp.Code) return false } } @@ -111,14 +111,14 @@ func (e *RequestExpect) Ensure(fns ...EnsureFunc) { if len(fns) == 0 { if !bytes.Equal(e.expectResp, ret.Content) { - flog.Trace("Response info: %+v", ret) + flog.Tracef("Response info: %+v", ret) } ExpectEqualValuesWithOffset(1, ret.Content, e.expectResp, e.explain...) } else { for _, fn := range fns { ok := fn(ret) if !ok { - flog.Trace("Response info: %+v", ret) + flog.Tracef("Response info: %+v", ret) } ExpectTrueWithOffset(1, ok, e.explain...) } diff --git a/test/e2e/legacy/features/monitor.go b/test/e2e/legacy/features/monitor.go index 8968df9f..75aa183b 100644 --- a/test/e2e/legacy/features/monitor.go +++ b/test/e2e/legacy/features/monitor.go @@ -41,7 +41,7 @@ var _ = ginkgo.Describe("[Feature: Monitor]", func() { framework.NewRequestExpect(f).RequestModify(func(r *request.Request) { r.HTTP().Port(dashboardPort).HTTPPath("/metrics") }).Ensure(func(resp *request.Response) bool { - log.Trace("prometheus metrics response: \n%s", resp.Content) + log.Tracef("prometheus metrics response: \n%s", resp.Content) if resp.Code != 200 { return false } diff --git a/test/e2e/legacy/features/real_ip.go b/test/e2e/legacy/features/real_ip.go index 082df8c6..f74c62d2 100644 --- a/test/e2e/legacy/features/real_ip.go +++ b/test/e2e/legacy/features/real_ip.go @@ -66,7 +66,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { rd := bufio.NewReader(c) ppHeader, err := pp.Read(rd) if err != nil { - log.Error("read proxy protocol error: %v", err) + log.Errorf("read proxy protocol error: %v", err) return } @@ -93,7 +93,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { f.RunProcesses([]string{serverConf}, []string{clientConf}) framework.NewRequestExpect(f).Port(remotePort).Ensure(func(resp *request.Response) bool { - log.Trace("ProxyProtocol get SourceAddr: %s", string(resp.Content)) + log.Tracef("ProxyProtocol get SourceAddr: %s", string(resp.Content)) addr, err := net.ResolveTCPAddr("tcp", string(resp.Content)) if err != nil { return false @@ -121,7 +121,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { rd := bufio.NewReader(c) ppHeader, err := pp.Read(rd) if err != nil { - log.Error("read proxy protocol error: %v", err) + log.Errorf("read proxy protocol error: %v", err) return } srcAddrRecord = ppHeader.SourceAddr.String() @@ -142,7 +142,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { r.HTTP().HTTPHost("normal.example.com") }).Ensure(framework.ExpectResponseCode(404)) - log.Trace("ProxyProtocol get SourceAddr: %s", srcAddrRecord) + log.Tracef("ProxyProtocol get SourceAddr: %s", srcAddrRecord) addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord) framework.ExpectNoError(err, srcAddrRecord) framework.ExpectEqualValues("127.0.0.1", addr.IP.String()) diff --git a/test/e2e/pkg/plugin/plugin.go b/test/e2e/pkg/plugin/plugin.go index 51de01d9..b807a060 100644 --- a/test/e2e/pkg/plugin/plugin.go +++ b/test/e2e/pkg/plugin/plugin.go @@ -26,7 +26,7 @@ func NewHTTPPluginServer(port int, newFunc NewPluginRequest, handler Handler, tl w.WriteHeader(500) return } - log.Trace("plugin request: %s", string(buf)) + log.Tracef("plugin request: %s", string(buf)) err = json.Unmarshal(buf, &r) if err != nil { w.WriteHeader(500) @@ -34,7 +34,7 @@ func NewHTTPPluginServer(port int, newFunc NewPluginRequest, handler Handler, tl } resp := handler(r) buf, _ = json.Marshal(resp) - log.Trace("plugin response: %s", string(buf)) + log.Tracef("plugin response: %s", string(buf)) _, _ = w.Write(buf) })), ) diff --git a/test/e2e/v1/features/monitor.go b/test/e2e/v1/features/monitor.go index 5d4b8f9f..fe92203a 100644 --- a/test/e2e/v1/features/monitor.go +++ b/test/e2e/v1/features/monitor.go @@ -42,7 +42,7 @@ var _ = ginkgo.Describe("[Feature: Monitor]", func() { framework.NewRequestExpect(f).RequestModify(func(r *request.Request) { r.HTTP().Port(dashboardPort).HTTPPath("/metrics") }).Ensure(func(resp *request.Response) bool { - log.Trace("prometheus metrics response: \n%s", resp.Content) + log.Tracef("prometheus metrics response: \n%s", resp.Content) if resp.Code != 200 { return false } diff --git a/test/e2e/v1/features/real_ip.go b/test/e2e/v1/features/real_ip.go index 85338c62..11febaa2 100644 --- a/test/e2e/v1/features/real_ip.go +++ b/test/e2e/v1/features/real_ip.go @@ -67,7 +67,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { rd := bufio.NewReader(c) ppHeader, err := pp.Read(rd) if err != nil { - log.Error("read proxy protocol error: %v", err) + log.Errorf("read proxy protocol error: %v", err) return } @@ -95,7 +95,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { f.RunProcesses([]string{serverConf}, []string{clientConf}) framework.NewRequestExpect(f).Port(remotePort).Ensure(func(resp *request.Response) bool { - log.Trace("ProxyProtocol get SourceAddr: %s", string(resp.Content)) + log.Tracef("ProxyProtocol get SourceAddr: %s", string(resp.Content)) addr, err := net.ResolveTCPAddr("tcp", string(resp.Content)) if err != nil { return false @@ -123,7 +123,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { rd := bufio.NewReader(c) ppHeader, err := pp.Read(rd) if err != nil { - log.Error("read proxy protocol error: %v", err) + log.Errorf("read proxy protocol error: %v", err) return } srcAddrRecord = ppHeader.SourceAddr.String() @@ -145,7 +145,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() { r.HTTP().HTTPHost("normal.example.com") }).Ensure(framework.ExpectResponseCode(404)) - log.Trace("ProxyProtocol get SourceAddr: %s", srcAddrRecord) + log.Tracef("ProxyProtocol get SourceAddr: %s", srcAddrRecord) addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord) framework.ExpectNoError(err, srcAddrRecord) framework.ExpectEqualValues("127.0.0.1", addr.IP.String())