Browse Source

use new log package (#4054)

pull/4055/head
fatedier 8 months ago committed by GitHub
parent
commit
43ba7bd338
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
  1. 38
      client/admin_api.go
  2. 6
      client/connector.go
  3. 26
      client/control.go
  4. 8
      client/health/health.go
  5. 18
      client/proxy/proxy.go
  6. 4
      client/proxy/proxy_manager.go
  7. 12
      client/proxy/proxy_wrapper.go
  8. 22
      client/proxy/sudp.go
  9. 20
      client/proxy/udp.go
  10. 34
      client/proxy/xtcp.go
  11. 14
      client/service.go
  12. 14
      client/visitor/stcp.go
  13. 32
      client/visitor/sudp.go
  14. 12
      client/visitor/visitor_manager.go
  15. 48
      client/visitor/xtcp.go
  16. 6
      cmd/frpc/sub/root.go
  17. 8
      cmd/frps/root.go
  18. 7
      go.mod
  19. 18
      go.sum
  20. 4
      pkg/metrics/mem/server.go
  21. 22
      pkg/nathole/controller.go
  22. 24
      pkg/nathole/nathole.go
  23. 12
      pkg/plugin/server/manager.go
  24. 4
      pkg/ssh/gateway.go
  25. 6
      pkg/ssh/server.go
  26. 91
      pkg/util/log/log.go
  27. 14
      pkg/util/vhost/http.go
  28. 4
      pkg/util/vhost/resource.go
  29. 16
      pkg/util/vhost/vhost.go
  30. 20
      pkg/util/xlog/xlog.go
  31. 34
      server/control.go
  32. 30
      server/dashboard_api.go
  33. 8
      server/proxy/http.go
  34. 4
      server/proxy/https.go
  35. 26
      server/proxy/proxy.go
  36. 2
      server/proxy/stcp.go
  37. 2
      server/proxy/sudp.go
  38. 4
      server/proxy/tcp.go
  39. 2
      server/proxy/tcpmux.go
  40. 26
      server/proxy/udp.go
  41. 2
      server/proxy/xtcp.go
  42. 52
      server/service.go
  43. 2
      test/e2e/e2e.go
  44. 2
      test/e2e/e2e_test.go
  45. 4
      test/e2e/framework/process.go
  46. 6
      test/e2e/framework/request.go
  47. 2
      test/e2e/legacy/features/monitor.go
  48. 8
      test/e2e/legacy/features/real_ip.go
  49. 4
      test/e2e/pkg/plugin/plugin.go
  50. 2
      test/e2e/v1/features/monitor.go
  51. 8
      test/e2e/v1/features/real_ip.go

38
client/admin_api.go

@ -76,9 +76,9 @@ func (svr *Service) apiReload(w http.ResponseWriter, r *http.Request) {
strictConfigMode, _ = strconv.ParseBool(strictStr) strictConfigMode, _ = strconv.ParseBool(strictStr)
} }
log.Info("api request [/api/reload]") log.Infof("api request [/api/reload]")
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
@ -89,32 +89,32 @@ func (svr *Service) apiReload(w http.ResponseWriter, r *http.Request) {
if err != nil { if err != nil {
res.Code = 400 res.Code = 400
res.Msg = err.Error() 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 return
} }
if _, err := validation.ValidateAllClientConfig(cliCfg, proxyCfgs, visitorCfgs); err != nil { if _, err := validation.ValidateAllClientConfig(cliCfg, proxyCfgs, visitorCfgs); err != nil {
res.Code = 400 res.Code = 400
res.Msg = err.Error() 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 return
} }
if err := svr.UpdateAllConfigurer(proxyCfgs, visitorCfgs); err != nil { if err := svr.UpdateAllConfigurer(proxyCfgs, visitorCfgs); err != nil {
res.Code = 500 res.Code = 500
res.Msg = err.Error() 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 return
} }
log.Info("success reload conf") log.Infof("success reload conf")
} }
// POST /api/stop // POST /api/stop
func (svr *Service) apiStop(w http.ResponseWriter, _ *http.Request) { func (svr *Service) apiStop(w http.ResponseWriter, _ *http.Request) {
res := GeneralResponse{Code: 200} res := GeneralResponse{Code: 200}
log.Info("api request [/api/stop]") log.Infof("api request [/api/stop]")
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
@ -165,9 +165,9 @@ func (svr *Service) apiStatus(w http.ResponseWriter, _ *http.Request) {
res StatusResp = make(map[string][]ProxyStatusResp) res StatusResp = make(map[string][]ProxyStatusResp)
) )
log.Info("Http request [/api/status]") log.Infof("Http request [/api/status]")
defer func() { defer func() {
log.Info("Http response [/api/status]") log.Infof("Http response [/api/status]")
buf, _ = json.Marshal(&res) buf, _ = json.Marshal(&res)
_, _ = w.Write(buf) _, _ = 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) { func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) {
res := GeneralResponse{Code: 200} res := GeneralResponse{Code: 200}
log.Info("Http get request [/api/config]") log.Infof("Http get request [/api/config]")
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
@ -210,7 +210,7 @@ func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) {
if svr.configFilePath == "" { if svr.configFilePath == "" {
res.Code = 400 res.Code = 400
res.Msg = "frpc has no config file path" res.Msg = "frpc has no config file path"
log.Warn("%s", res.Msg) log.Warnf("%s", res.Msg)
return return
} }
@ -218,7 +218,7 @@ func (svr *Service) apiGetConfig(w http.ResponseWriter, _ *http.Request) {
if err != nil { if err != nil {
res.Code = 400 res.Code = 400
res.Msg = err.Error() 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 return
} }
res.Msg = string(content) 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) { func (svr *Service) apiPutConfig(w http.ResponseWriter, r *http.Request) {
res := GeneralResponse{Code: 200} res := GeneralResponse{Code: 200}
log.Info("Http put request [/api/config]") log.Infof("Http put request [/api/config]")
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
@ -242,21 +242,21 @@ func (svr *Service) apiPutConfig(w http.ResponseWriter, r *http.Request) {
if err != nil { if err != nil {
res.Code = 400 res.Code = 400
res.Msg = fmt.Sprintf("read request body error: %v", err) res.Msg = fmt.Sprintf("read request body error: %v", err)
log.Warn("%s", res.Msg) log.Warnf("%s", res.Msg)
return return
} }
if len(body) == 0 { if len(body) == 0 {
res.Code = 400 res.Code = 400
res.Msg = "body can't be empty" res.Msg = "body can't be empty"
log.Warn("%s", res.Msg) log.Warnf("%s", res.Msg)
return return
} }
if err := os.WriteFile(svr.configFilePath, body, 0o644); err != nil { if err := os.WriteFile(svr.configFilePath, body, 0o644); err != nil {
res.Code = 500 res.Code = 500
res.Msg = fmt.Sprintf("write content to frpc config file error: %v", err) res.Msg = fmt.Sprintf("write content to frpc config file error: %v", err)
log.Warn("%s", res.Msg) log.Warnf("%s", res.Msg)
return return
} }
} }

6
client/connector.go

@ -84,7 +84,7 @@ func (c *defaultConnectorImpl) Open() error {
tlsConfig, err = transport.NewClientTLSConfig("", "", "", sn) tlsConfig, err = transport.NewClientTLSConfig("", "", "", sn)
} }
if err != nil { 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 return err
} }
tlsConfig.NextProtos = []string{"frp"} tlsConfig.NextProtos = []string{"frp"}
@ -164,14 +164,14 @@ func (c *defaultConnectorImpl) realConnect() (net.Conn, error) {
c.cfg.Transport.TLS.TrustedCaFile, c.cfg.Transport.TLS.TrustedCaFile,
sn) sn)
if err != nil { 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 return nil, err
} }
} }
proxyType, addr, auth, err := libdial.ParseProxyURL(c.cfg.Transport.ProxyURL) proxyType, addr, auth, err := libdial.ParseProxyURL(c.cfg.Transport.ProxyURL)
if err != nil { if err != nil {
xl.Error("fail to parse proxy url") xl.Errorf("fail to parse proxy url")
return nil, err return nil, err
} }
dialOptions := []libdial.DialOption{} dialOptions := []libdial.DialOption{}

26
client/control.go

@ -124,7 +124,7 @@ func (ctl *Control) handleReqWorkConn(_ msg.Message) {
xl := ctl.xl xl := ctl.xl
workConn, err := ctl.connectServer() workConn, err := ctl.connectServer()
if err != nil { if err != nil {
xl.Warn("start new connection to server error: %v", err) xl.Warnf("start new connection to server error: %v", err)
return return
} }
@ -132,24 +132,24 @@ func (ctl *Control) handleReqWorkConn(_ msg.Message) {
RunID: ctl.sessionCtx.RunID, RunID: ctl.sessionCtx.RunID,
} }
if err = ctl.sessionCtx.AuthSetter.SetNewWorkConn(m); err != nil { 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() workConn.Close()
return return
} }
if err = msg.WriteMsg(workConn, m); err != nil { 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() workConn.Close()
return return
} }
var startMsg msg.StartWorkConn var startMsg msg.StartWorkConn
if err = msg.ReadMsgInto(workConn, &startMsg); err != nil { 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() workConn.Close()
return return
} }
if startMsg.Error != "" { if startMsg.Error != "" {
xl.Error("StartWorkConn contains error: %s", startMsg.Error) xl.Errorf("StartWorkConn contains error: %s", startMsg.Error)
workConn.Close() workConn.Close()
return return
} }
@ -165,9 +165,9 @@ func (ctl *Control) handleNewProxyResp(m msg.Message) {
// Start a new proxy handler if no error got // Start a new proxy handler if no error got
err := ctl.pm.StartProxy(inMsg.ProxyName, inMsg.RemoteAddr, inMsg.Error) err := ctl.pm.StartProxy(inMsg.ProxyName, inMsg.RemoteAddr, inMsg.Error)
if err != nil { if err != nil {
xl.Warn("[%s] start error: %v", inMsg.ProxyName, err) xl.Warnf("[%s] start error: %v", inMsg.ProxyName, err)
} else { } 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. // Dispatch the NatHoleResp message to the related proxy.
ok := ctl.msgTransporter.DispatchWithType(inMsg, msg.TypeNameNatHoleResp, inMsg.TransactionID) ok := ctl.msgTransporter.DispatchWithType(inMsg, msg.TypeNameNatHoleResp, inMsg.TransactionID)
if !ok { 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) inMsg := m.(*msg.Pong)
if inMsg.Error != "" { if inMsg.Error != "" {
xl.Error("Pong message contains error: %s", inMsg.Error) xl.Errorf("Pong message contains error: %s", inMsg.Error)
ctl.closeSession() ctl.closeSession()
return return
} }
ctl.lastPong.Store(time.Now()) ctl.lastPong.Store(time.Now())
xl.Debug("receive heartbeat from server") xl.Debugf("receive heartbeat from server")
} }
// closeSession closes the control connection. // closeSession closes the control connection.
@ -241,10 +241,10 @@ func (ctl *Control) heartbeatWorker() {
if ctl.sessionCtx.Common.Transport.HeartbeatInterval > 0 { if ctl.sessionCtx.Common.Transport.HeartbeatInterval > 0 {
// send heartbeat to server // send heartbeat to server
sendHeartBeat := func() (bool, error) { sendHeartBeat := func() (bool, error) {
xl.Debug("send heartbeat to server") xl.Debugf("send heartbeat to server")
pingMsg := &msg.Ping{} pingMsg := &msg.Ping{}
if err := ctl.sessionCtx.AuthSetter.SetPing(pingMsg); err != nil { 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 return false, err
} }
_ = ctl.msgDispatcher.Send(pingMsg) _ = ctl.msgDispatcher.Send(pingMsg)
@ -269,7 +269,7 @@ func (ctl *Control) heartbeatWorker() {
go wait.Until(func() { go wait.Until(func() {
if time.Since(ctl.lastPong.Load().(time.Time)) > time.Duration(ctl.sessionCtx.Common.Transport.HeartbeatTimeout)*time.Second { 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() ctl.closeSession()
return return
} }

8
client/health/health.go

@ -112,17 +112,17 @@ func (monitor *Monitor) checkWorker() {
} }
if err == nil { if err == nil {
xl.Trace("do one health check success") xl.Tracef("do one health check success")
if !monitor.statusOK && monitor.statusNormalFn != nil { 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.statusOK = true
monitor.statusNormalFn() monitor.statusNormalFn()
} }
} else { } else {
xl.Warn("do one health check failed: %v", err) xl.Warnf("do one health check failed: %v", err)
monitor.failedTimes++ monitor.failedTimes++
if monitor.statusOK && int(monitor.failedTimes) >= monitor.maxFailedTimes && monitor.statusFailedFn != nil { 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.statusOK = false
monitor.statusFailedFn() monitor.statusFailedFn()
} }

18
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) baseCfg.Transport.UseEncryption, baseCfg.Transport.UseCompression)
if baseCfg.Transport.UseEncryption { if baseCfg.Transport.UseEncryption {
remote, err = libio.WithEncryption(remote, encKey) remote, err = libio.WithEncryption(remote, encKey)
if err != nil { if err != nil {
workConn.Close() workConn.Close()
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }
@ -189,9 +189,9 @@ func (pxy *BaseProxy) HandleTCPWorkConnection(workConn net.Conn, m *msg.StartWor
if pxy.proxyPlugin != nil { if pxy.proxyPlugin != nil {
// if plugin is set, let plugin handle connection first // 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) pxy.proxyPlugin.Handle(remote, workConn, &extraInfo)
xl.Debug("handle by plugin finished") xl.Debugf("handle by plugin finished")
return return
} }
@ -201,25 +201,25 @@ func (pxy *BaseProxy) HandleTCPWorkConnection(workConn net.Conn, m *msg.StartWor
) )
if err != nil { if err != nil {
workConn.Close() 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 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()) localConn.RemoteAddr().String(), workConn.LocalAddr().String(), workConn.RemoteAddr().String())
if extraInfo.ProxyProtocolHeader != nil { if extraInfo.ProxyProtocolHeader != nil {
if _, err := extraInfo.ProxyProtocolHeader.WriteTo(localConn); err != nil { if _, err := extraInfo.ProxyProtocolHeader.WriteTo(localConn); err != nil {
workConn.Close() 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 return
} }
} }
_, _, errs := libio.Join(localConn, remote) _, _, errs := libio.Join(localConn, remote)
xl.Debug("join connections closed") xl.Debugf("join connections closed")
if len(errs) > 0 { if len(errs) > 0 {
xl.Trace("join connections errors: %v", errs) xl.Tracef("join connections errors: %v", errs)
} }
if compressionResourceRecycleFn != nil { if compressionResourceRecycleFn != nil {
compressionResourceRecycleFn() compressionResourceRecycleFn()

4
client/proxy/proxy_manager.go

@ -152,7 +152,7 @@ func (pm *Manager) UpdateAll(proxyCfgs []v1.ProxyConfigurer) {
} }
} }
if len(delPxyNames) > 0 { if len(delPxyNames) > 0 {
xl.Info("proxy removed: %s", delPxyNames) xl.Infof("proxy removed: %s", delPxyNames)
} }
addPxyNames := make([]string, 0) addPxyNames := make([]string, 0)
@ -170,6 +170,6 @@ func (pm *Manager) UpdateAll(proxyCfgs []v1.ProxyConfigurer) {
} }
} }
if len(addPxyNames) > 0 { if len(addPxyNames) > 0 {
xl.Info("proxy added: %s", addPxyNames) xl.Infof("proxy added: %s", addPxyNames)
} }
} }

12
client/proxy/proxy_wrapper.go

@ -114,7 +114,7 @@ func NewWrapper(
addr := net.JoinHostPort(baseInfo.LocalIP, strconv.Itoa(baseInfo.LocalPort)) addr := net.JoinHostPort(baseInfo.LocalIP, strconv.Itoa(baseInfo.LocalPort))
pw.monitor = health.NewMonitor(pw.ctx, baseInfo.HealthCheck, addr, pw.monitor = health.NewMonitor(pw.ctx, baseInfo.HealthCheck, addr,
pw.statusNormalCallback, pw.statusFailedCallback) 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) 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 == ProxyPhaseWaitStart && now.After(pw.lastSendStartMsg.Add(waitResponseTimeout))) ||
(pw.Phase == ProxyPhaseStartErr && now.After(pw.lastStartErr.Add(startErrTimeout))) { (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 pw.Phase = ProxyPhaseWaitStart
var newProxyMsg msg.NewProxy var newProxyMsg msg.NewProxy
@ -212,7 +212,7 @@ func (pw *Wrapper) checkWorker() {
pw.mu.Lock() pw.mu.Lock()
if pw.Phase == ProxyPhaseRunning || pw.Phase == ProxyPhaseWaitStart { if pw.Phase == ProxyPhaseRunning || pw.Phase == ProxyPhaseWaitStart {
pw.close() 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.Phase = ProxyPhaseCheckFailed
} }
pw.mu.Unlock() pw.mu.Unlock()
@ -236,7 +236,7 @@ func (pw *Wrapper) statusNormalCallback() {
default: default:
} }
}) })
xl.Info("health check success") xl.Infof("health check success")
} }
func (pw *Wrapper) statusFailedCallback() { func (pw *Wrapper) statusFailedCallback() {
@ -248,7 +248,7 @@ func (pw *Wrapper) statusFailedCallback() {
default: default:
} }
}) })
xl.Info("health check failed") xl.Infof("health check failed")
} }
func (pw *Wrapper) InWorkConn(workConn net.Conn, m *msg.StartWorkConn) { 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 pxy := pw.pxy
pw.mu.RUnlock() pw.mu.RUnlock()
if pxy != nil && pw.Phase == ProxyPhaseRunning { 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) go pxy.InWorkConn(workConn, m)
} else { } else {
workConn.Close() workConn.Close()

22
client/proxy/sudp.go

@ -81,7 +81,7 @@ func (pxy *SUDPProxy) Close() {
func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
xl := pxy.xl 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 rwc io.ReadWriteCloser = conn
var err error 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)) rwc, err = libio.WithEncryption(rwc, []byte(pxy.clientCfg.Auth.Token))
if err != nil { if err != nil {
conn.Close() conn.Close()
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }
@ -133,21 +133,21 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
// first to check sudp proxy is closed or not // first to check sudp proxy is closed or not
select { select {
case <-pxy.closeCh: case <-pxy.closeCh:
xl.Trace("frpc sudp proxy is closed") xl.Tracef("frpc sudp proxy is closed")
return return
default: default:
} }
var udpMsg msg.UDPPacket var udpMsg msg.UDPPacket
if errRet := msg.ReadMsgInto(conn, &udpMsg); errRet != nil { 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 return
} }
if errRet := errors.PanicToError(func() { if errRet := errors.PanicToError(func() {
readCh <- &udpMsg readCh <- &udpMsg
}); errRet != nil { }); 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 return
} }
} }
@ -157,21 +157,21 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) { workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) {
defer func() { defer func() {
closeFn() closeFn()
xl.Info("writer goroutine for sudp work connection closed") xl.Infof("writer goroutine for sudp work connection closed")
}() }()
var errRet error var errRet error
for rawMsg := range sendCh { for rawMsg := range sendCh {
switch m := rawMsg.(type) { switch m := rawMsg.(type) {
case *msg.UDPPacket: 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()) m.LocalAddr.String(), m.RemoteAddr.String(), conn.LocalAddr().String(), conn.RemoteAddr().String())
case *msg.Ping: 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 { 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 return
} }
} }
@ -191,11 +191,11 @@ func (pxy *SUDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
if errRet = errors.PanicToError(func() { if errRet = errors.PanicToError(func() {
sendCh <- &msg.Ping{} sendCh <- &msg.Ping{}
}); errRet != nil { }); errRet != nil {
xl.Warn("heartbeat goroutine for sudp work connection closed") xl.Warnf("heartbeat goroutine for sudp work connection closed")
return return
} }
case <-pxy.closeCh: case <-pxy.closeCh:
xl.Trace("frpc sudp proxy is closed") xl.Tracef("frpc sudp proxy is closed")
return return
} }
} }

20
client/proxy/udp.go

@ -90,7 +90,7 @@ func (pxy *UDPProxy) Close() {
func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) { func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
xl := pxy.xl 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 // close resources related with old workConn
pxy.Close() 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)) rwc, err = libio.WithEncryption(rwc, []byte(pxy.clientCfg.Auth.Token))
if err != nil { if err != nil {
conn.Close() conn.Close()
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }
@ -125,32 +125,32 @@ func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
for { for {
var udpMsg msg.UDPPacket var udpMsg msg.UDPPacket
if errRet := msg.ReadMsgInto(conn, &udpMsg); errRet != nil { 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 return
} }
if errRet := errors.PanicToError(func() { 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 readCh <- &udpMsg
}); errRet != nil { }); 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 return
} }
} }
} }
workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) { workConnSenderFn := func(conn net.Conn, sendCh chan msg.Message) {
defer func() { defer func() {
xl.Info("writer goroutine for udp work connection closed") xl.Infof("writer goroutine for udp work connection closed")
}() }()
var errRet error var errRet error
for rawMsg := range sendCh { for rawMsg := range sendCh {
switch m := rawMsg.(type) { switch m := rawMsg.(type) {
case *msg.UDPPacket: 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: 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 { 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 return
} }
} }
@ -162,7 +162,7 @@ func (pxy *UDPProxy) InWorkConn(conn net.Conn, _ *msg.StartWorkConn) {
if errRet = errors.PanicToError(func() { if errRet = errors.PanicToError(func() {
sendCh <- &msg.Ping{} sendCh <- &msg.Ping{}
}); errRet != nil { }); errRet != nil {
xl.Trace("heartbeat goroutine for udp work connection closed") xl.Tracef("heartbeat goroutine for udp work connection closed")
break break
} }
} }

34
client/proxy/xtcp.go

@ -59,17 +59,17 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC
var natHoleSidMsg msg.NatHoleSid var natHoleSidMsg msg.NatHoleSid
err := msg.ReadMsgInto(conn, &natHoleSidMsg) err := msg.ReadMsgInto(conn, &natHoleSidMsg)
if err != nil { if err != nil {
xl.Error("xtcp read from workConn error: %v", err) xl.Errorf("xtcp read from workConn error: %v", err)
return return
} }
xl.Trace("nathole prepare start") xl.Tracef("nathole prepare start")
prepareResult, err := nathole.Prepare([]string{pxy.clientCfg.NatHoleSTUNServer}) prepareResult, err := nathole.Prepare([]string{pxy.clientCfg.NatHoleSTUNServer})
if err != nil { if err != nil {
xl.Warn("nathole prepare error: %v", err) xl.Warnf("nathole prepare error: %v", err)
return 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) prepareResult.NatType, prepareResult.Behavior, prepareResult.Addrs, prepareResult.AssistedAddrs)
defer prepareResult.ListenConn.Close() defer prepareResult.ListenConn.Close()
@ -83,14 +83,14 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC
AssistedAddrs: prepareResult.AssistedAddrs, 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) natHoleRespMsg, err := nathole.ExchangeInfo(pxy.ctx, pxy.msgTransporter, transactionID, natHoleClientMsg, 5*time.Second)
if err != nil { if err != nil {
xl.Warn("nathole exchange info error: %v", err) xl.Warnf("nathole exchange info error: %v", err)
return 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.Sid, natHoleRespMsg.Protocol, natHoleRespMsg.CandidateAddrs,
natHoleRespMsg.AssistedAddrs, natHoleRespMsg.DetectBehavior) 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)) newListenConn, raddr, err := nathole.MakeHole(pxy.ctx, listenConn, natHoleRespMsg, []byte(pxy.cfg.Secretkey))
if err != nil { if err != nil {
listenConn.Close() listenConn.Close()
xl.Warn("make hole error: %v", err) xl.Warnf("make hole error: %v", err)
_ = pxy.msgTransporter.Send(&msg.NatHoleReport{ _ = pxy.msgTransporter.Send(&msg.NatHoleReport{
Sid: natHoleRespMsg.Sid, Sid: natHoleRespMsg.Sid,
Success: false, Success: false,
@ -106,7 +106,7 @@ func (pxy *XTCPProxy) InWorkConn(conn net.Conn, startWorkConnMsg *msg.StartWorkC
return return
} }
listenConn = newListenConn 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{ _ = pxy.msgTransporter.Send(&msg.NatHoleReport{
Sid: natHoleRespMsg.Sid, 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()) laddr, _ := net.ResolveUDPAddr("udp", listenConn.LocalAddr().String())
lConn, err := net.DialUDP("udp", laddr, raddr) lConn, err := net.DialUDP("udp", laddr, raddr)
if err != nil { if err != nil {
xl.Warn("dial udp error: %v", err) xl.Warnf("dial udp error: %v", err)
return return
} }
defer lConn.Close() defer lConn.Close()
remote, err := netpkg.NewKCPConnFromUDP(lConn, true, raddr.String()) remote, err := netpkg.NewKCPConnFromUDP(lConn, true, raddr.String())
if err != nil { 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 return
} }
@ -145,7 +145,7 @@ func (pxy *XTCPProxy) listenByKCP(listenConn *net.UDPConn, raddr *net.UDPAddr, s
fmuxCfg.LogOutput = io.Discard fmuxCfg.LogOutput = io.Discard
session, err := fmux.Server(remote, fmuxCfg) session, err := fmux.Server(remote, fmuxCfg)
if err != nil { if err != nil {
xl.Error("create mux session error: %v", err) xl.Errorf("create mux session error: %v", err)
return return
} }
defer session.Close() defer session.Close()
@ -153,7 +153,7 @@ func (pxy *XTCPProxy) listenByKCP(listenConn *net.UDPConn, raddr *net.UDPAddr, s
for { for {
muxConn, err := session.Accept() muxConn, err := session.Accept()
if err != nil { if err != nil {
xl.Error("accept connection error: %v", err) xl.Errorf("accept connection error: %v", err)
return return
} }
go pxy.HandleTCPWorkConnection(muxConn, startWorkConnMsg, []byte(pxy.cfg.Secretkey)) 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("", "", "") tlsConfig, err := transport.NewServerTLSConfig("", "", "")
if err != nil { if err != nil {
xl.Warn("create tls config error: %v", err) xl.Warnf("create tls config error: %v", err)
return return
} }
tlsConfig.NextProtos = []string{"frp"} tlsConfig.NextProtos = []string{"frp"}
@ -178,19 +178,19 @@ func (pxy *XTCPProxy) listenByQUIC(listenConn *net.UDPConn, _ *net.UDPAddr, star
}, },
) )
if err != nil { if err != nil {
xl.Warn("dial quic error: %v", err) xl.Warnf("dial quic error: %v", err)
return return
} }
// only accept one connection from raddr // only accept one connection from raddr
c, err := quicListener.Accept(pxy.ctx) c, err := quicListener.Accept(pxy.ctx)
if err != nil { if err != nil {
xl.Error("quic accept connection error: %v", err) xl.Errorf("quic accept connection error: %v", err)
return return
} }
for { for {
stream, err := c.AcceptStream(pxy.ctx) stream, err := c.AcceptStream(pxy.ctx)
if err != nil { if err != nil {
xl.Debug("quic accept stream error: %v", err) xl.Debugf("quic accept stream error: %v", err)
_ = c.CloseWithError(0, "") _ = c.CloseWithError(0, "")
return return
} }

14
client/service.go

@ -174,9 +174,9 @@ func (svr *Service) Run(ctx context.Context) error {
if svr.webServer != nil { if svr.webServer != nil {
go func() { 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 { 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 != "" { if loginRespMsg.Error != "" {
err = fmt.Errorf("%s", loginRespMsg.Error) err = fmt.Errorf("%s", loginRespMsg.Error)
xl.Error("%s", loginRespMsg.Error) xl.Errorf("%s", loginRespMsg.Error)
return return
} }
svr.runID = loginRespMsg.RunID svr.runID = loginRespMsg.RunID
xl.AddPrefix(xlog.LogPrefix{Name: "runID", Value: svr.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 return
} }
@ -284,10 +284,10 @@ func (svr *Service) loopLoginUntilSuccess(maxInterval time.Duration, firstLoginE
xl := xlog.FromContextSafe(svr.ctx) xl := xlog.FromContextSafe(svr.ctx)
loginFunc := func() (bool, error) { loginFunc := func() (bool, error) {
xl.Info("try to connect to server...") xl.Infof("try to connect to server...")
conn, connector, err := svr.login() conn, connector, err := svr.login()
if err != nil { if err != nil {
xl.Warn("connect to server error: %v", err) xl.Warnf("connect to server error: %v", err)
if firstLoginExit { if firstLoginExit {
svr.cancel(cancelErr{Err: err}) svr.cancel(cancelErr{Err: err})
} }
@ -313,7 +313,7 @@ func (svr *Service) loopLoginUntilSuccess(maxInterval time.Duration, firstLoginE
ctl, err := NewControl(svr.ctx, sessionCtx) ctl, err := NewControl(svr.ctx, sessionCtx)
if err != nil { if err != nil {
conn.Close() conn.Close()
xl.Error("NewControl error: %v", err) xl.Errorf("NewControl error: %v", err)
return false, err return false, err
} }
ctl.SetInWorkConnCallback(svr.handleWorkConnCb) ctl.SetInWorkConnCallback(svr.handleWorkConnCb)

14
client/visitor/stcp.go

@ -56,7 +56,7 @@ func (sv *STCPVisitor) worker() {
for { for {
conn, err := sv.l.Accept() conn, err := sv.l.Accept()
if err != nil { if err != nil {
xl.Warn("stcp local listener closed") xl.Warnf("stcp local listener closed")
return return
} }
go sv.handleConn(conn) go sv.handleConn(conn)
@ -68,7 +68,7 @@ func (sv *STCPVisitor) internalConnWorker() {
for { for {
conn, err := sv.internalLn.Accept() conn, err := sv.internalLn.Accept()
if err != nil { if err != nil {
xl.Warn("stcp internal listener closed") xl.Warnf("stcp internal listener closed")
return return
} }
go sv.handleConn(conn) go sv.handleConn(conn)
@ -79,7 +79,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) {
xl := xlog.FromContextSafe(sv.ctx) xl := xlog.FromContextSafe(sv.ctx)
defer userConn.Close() defer userConn.Close()
xl.Debug("get a new stcp user connection") xl.Debugf("get a new stcp user connection")
visitorConn, err := sv.helper.ConnectServer() visitorConn, err := sv.helper.ConnectServer()
if err != nil { if err != nil {
return return
@ -97,7 +97,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) {
} }
err = msg.WriteMsg(visitorConn, newVisitorConnMsg) err = msg.WriteMsg(visitorConn, newVisitorConnMsg)
if err != nil { if err != nil {
xl.Warn("send newVisitorConnMsg to server error: %v", err) xl.Warnf("send newVisitorConnMsg to server error: %v", err)
return return
} }
@ -105,13 +105,13 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) {
_ = visitorConn.SetReadDeadline(time.Now().Add(10 * time.Second)) _ = visitorConn.SetReadDeadline(time.Now().Add(10 * time.Second))
err = msg.ReadMsgInto(visitorConn, &newVisitorConnRespMsg) err = msg.ReadMsgInto(visitorConn, &newVisitorConnRespMsg)
if err != nil { if err != nil {
xl.Warn("get newVisitorConnRespMsg error: %v", err) xl.Warnf("get newVisitorConnRespMsg error: %v", err)
return return
} }
_ = visitorConn.SetReadDeadline(time.Time{}) _ = visitorConn.SetReadDeadline(time.Time{})
if newVisitorConnRespMsg.Error != "" { if newVisitorConnRespMsg.Error != "" {
xl.Warn("start new visitor connection error: %s", newVisitorConnRespMsg.Error) xl.Warnf("start new visitor connection error: %s", newVisitorConnRespMsg.Error)
return return
} }
@ -120,7 +120,7 @@ func (sv *STCPVisitor) handleConn(userConn net.Conn) {
if sv.cfg.Transport.UseEncryption { if sv.cfg.Transport.UseEncryption {
remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey)) remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }

32
client/visitor/sudp.go

@ -62,7 +62,7 @@ func (sv *SUDPVisitor) Run() (err error) {
sv.sendCh = make(chan *msg.UDPPacket, 1024) sv.sendCh = make(chan *msg.UDPPacket, 1024)
sv.readCh = 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 sv.dispatcher()
go udp.ForwardUserConn(sv.udpConn, sv.readCh, sv.sendCh, int(sv.clientCfg.UDPPacketSize)) go udp.ForwardUserConn(sv.udpConn, sv.readCh, sv.sendCh, int(sv.clientCfg.UDPPacketSize))
@ -84,17 +84,17 @@ func (sv *SUDPVisitor) dispatcher() {
select { select {
case firstPacket = <-sv.sendCh: case firstPacket = <-sv.sendCh:
if firstPacket == nil { if firstPacket == nil {
xl.Info("frpc sudp visitor proxy is closed") xl.Infof("frpc sudp visitor proxy is closed")
return return
} }
case <-sv.checkCloseCh: case <-sv.checkCloseCh:
xl.Info("frpc sudp visitor proxy is closed") xl.Infof("frpc sudp visitor proxy is closed")
return return
} }
visitorConn, err = sv.getNewVisitorConn() visitorConn, err = sv.getNewVisitorConn()
if err != nil { 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 continue
} }
@ -111,7 +111,7 @@ func (sv *SUDPVisitor) dispatcher() {
func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) { func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) {
xl := xlog.FromContextSafe(sv.ctx) xl := xlog.FromContextSafe(sv.ctx)
xl.Debug("starting sudp proxy worker") xl.Debugf("starting sudp proxy worker")
wg := &sync.WaitGroup{} wg := &sync.WaitGroup{}
wg.Add(2) 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 // frpc will send heartbeat in workConn to frpc visitor for keeping alive
_ = conn.SetReadDeadline(time.Now().Add(60 * time.Second)) _ = conn.SetReadDeadline(time.Now().Add(60 * time.Second))
if rawMsg, errRet = msg.ReadMsg(conn); errRet != nil { 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 return
} }
_ = conn.SetReadDeadline(time.Time{}) _ = conn.SetReadDeadline(time.Time{})
switch m := rawMsg.(type) { switch m := rawMsg.(type) {
case *msg.Ping: case *msg.Ping:
xl.Debug("frpc visitor get ping message from frpc") xl.Debugf("frpc visitor get ping message from frpc")
continue continue
case *msg.UDPPacket: case *msg.UDPPacket:
if errRet := errors.PanicToError(func() { if errRet := errors.PanicToError(func() {
sv.readCh <- m 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 { }); errRet != nil {
xl.Info("reader goroutine for udp work connection closed") xl.Infof("reader goroutine for udp work connection closed")
return return
} }
} }
@ -165,25 +165,25 @@ func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) {
var errRet error var errRet error
if firstPacket != nil { if firstPacket != nil {
if errRet = msg.WriteMsg(conn, firstPacket); errRet != 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 return
} }
xl.Trace("send udp package to workConn: %s", firstPacket.Content) xl.Tracef("send udp package to workConn: %s", firstPacket.Content)
} }
for { for {
select { select {
case udpMsg, ok := <-sv.sendCh: case udpMsg, ok := <-sv.sendCh:
if !ok { if !ok {
xl.Info("sender goroutine for udp work connection closed") xl.Infof("sender goroutine for udp work connection closed")
return return
} }
if errRet = msg.WriteMsg(conn, udpMsg); errRet != nil { 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 return
} }
xl.Trace("send udp package to workConn: %s", udpMsg.Content) xl.Tracef("send udp package to workConn: %s", udpMsg.Content)
case <-closeCh: case <-closeCh:
return return
} }
@ -194,7 +194,7 @@ func (sv *SUDPVisitor) worker(workConn net.Conn, firstPacket *msg.UDPPacket) {
go workConnSenderFn(workConn) go workConnSenderFn(workConn)
wg.Wait() wg.Wait()
xl.Info("sudp worker is closed") xl.Infof("sudp worker is closed")
} }
func (sv *SUDPVisitor) getNewVisitorConn() (net.Conn, error) { func (sv *SUDPVisitor) getNewVisitorConn() (net.Conn, error) {
@ -235,7 +235,7 @@ func (sv *SUDPVisitor) getNewVisitorConn() (net.Conn, error) {
if sv.cfg.Transport.UseEncryption { if sv.cfg.Transport.UseEncryption {
remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey)) remote, err = libio.WithEncryption(remote, []byte(sv.cfg.SecretKey))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return nil, err return nil, err
} }
} }

12
client/visitor/visitor_manager.go

@ -79,14 +79,14 @@ func (vm *Manager) keepVisitorsRunning() {
for { for {
select { select {
case <-vm.stopCh: case <-vm.stopCh:
xl.Trace("gracefully shutdown visitor manager") xl.Tracef("gracefully shutdown visitor manager")
return return
case <-ticker.C: case <-ticker.C:
vm.mu.Lock() vm.mu.Lock()
for _, cfg := range vm.cfgs { for _, cfg := range vm.cfgs {
name := cfg.GetBaseConfig().Name name := cfg.GetBaseConfig().Name
if _, exist := vm.visitors[name]; !exist { 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) _ = 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) visitor := NewVisitor(vm.ctx, cfg, vm.clientCfg, vm.helper)
err = visitor.Run() err = visitor.Run()
if err != nil { if err != nil {
xl.Warn("start error: %v", err) xl.Warnf("start error: %v", err)
} else { } else {
vm.visitors[name] = visitor vm.visitors[name] = visitor
xl.Info("start visitor success") xl.Infof("start visitor success")
} }
return return
} }
@ -156,7 +156,7 @@ func (vm *Manager) UpdateAll(cfgs []v1.VisitorConfigurer) {
} }
} }
if len(delNames) > 0 { if len(delNames) > 0 {
xl.Info("visitor removed: %v", delNames) xl.Infof("visitor removed: %v", delNames)
} }
addNames := make([]string, 0) addNames := make([]string, 0)
@ -169,7 +169,7 @@ func (vm *Manager) UpdateAll(cfgs []v1.VisitorConfigurer) {
} }
} }
if len(addNames) > 0 { if len(addNames) > 0 {
xl.Info("visitor added: %v", addNames) xl.Infof("visitor added: %v", addNames)
} }
} }

48
client/visitor/xtcp.go

@ -93,7 +93,7 @@ func (sv *XTCPVisitor) worker() {
for { for {
conn, err := sv.l.Accept() conn, err := sv.l.Accept()
if err != nil { if err != nil {
xl.Warn("xtcp local listener closed") xl.Warnf("xtcp local listener closed")
return return
} }
go sv.handleConn(conn) go sv.handleConn(conn)
@ -105,7 +105,7 @@ func (sv *XTCPVisitor) internalConnWorker() {
for { for {
conn, err := sv.internalLn.Accept() conn, err := sv.internalLn.Accept()
if err != nil { if err != nil {
xl.Warn("xtcp internal listener closed") xl.Warnf("xtcp internal listener closed")
return return
} }
go sv.handleConn(conn) go sv.handleConn(conn)
@ -140,14 +140,14 @@ func (sv *XTCPVisitor) keepTunnelOpenWorker() {
case <-sv.ctx.Done(): case <-sv.ctx.Done():
return return
case <-ticker.C: case <-ticker.C:
xl.Debug("keepTunnelOpenWorker try to check tunnel...") xl.Debugf("keepTunnelOpenWorker try to check tunnel...")
conn, err := sv.getTunnelConn() conn, err := sv.getTunnelConn()
if err != nil { 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) _ = sv.retryLimiter.Wait(sv.ctx)
continue continue
} }
xl.Debug("keepTunnelOpenWorker check success") xl.Debugf("keepTunnelOpenWorker check success")
if conn != nil { if conn != nil {
conn.Close() 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, // 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. // 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) tunnelConn, err := sv.openTunnel(ctx)
if err != nil { if err != nil {
xl.Error("open tunnel error: %v", err) xl.Errorf("open tunnel error: %v", err)
// no fallback, just return // no fallback, just return
if sv.cfg.FallbackTo == "" { if sv.cfg.FallbackTo == "" {
return 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 { 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 return
} }
isConnTrasfered = true isConnTrasfered = true
@ -195,7 +195,7 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) {
if sv.cfg.Transport.UseEncryption { if sv.cfg.Transport.UseEncryption {
muxConnRWCloser, err = libio.WithEncryption(muxConnRWCloser, []byte(sv.cfg.SecretKey)) muxConnRWCloser, err = libio.WithEncryption(muxConnRWCloser, []byte(sv.cfg.SecretKey))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }
@ -206,9 +206,9 @@ func (sv *XTCPVisitor) handleConn(userConn net.Conn) {
} }
_, _, errs := libio.Join(userConn, muxConnRWCloser) _, _, errs := libio.Join(userConn, muxConnRWCloser)
xl.Debug("join connections closed") xl.Debugf("join connections closed")
if len(errs) > 0 { 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 != nil {
if err != ErrNoTunnelSession { if err != ErrNoTunnelSession {
xl.Warn("get tunnel connection error: %v", err) xl.Warnf("get tunnel connection error: %v", err)
} }
continue continue
} }
@ -268,19 +268,19 @@ func (sv *XTCPVisitor) getTunnelConn() (net.Conn, error) {
// 4. Create a tunnel session using an underlying UDP connection. // 4. Create a tunnel session using an underlying UDP connection.
func (sv *XTCPVisitor) makeNatHole() { func (sv *XTCPVisitor) makeNatHole() {
xl := xlog.FromContextSafe(sv.ctx) 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 { 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 return
} }
xl.Trace("nathole prepare start") xl.Tracef("nathole prepare start")
prepareResult, err := nathole.Prepare([]string{sv.clientCfg.NatHoleSTUNServer}) prepareResult, err := nathole.Prepare([]string{sv.clientCfg.NatHoleSTUNServer})
if err != nil { if err != nil {
xl.Warn("nathole prepare error: %v", err) xl.Warnf("nathole prepare error: %v", err)
return 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) prepareResult.NatType, prepareResult.Behavior, prepareResult.Addrs, prepareResult.AssistedAddrs)
listenConn := prepareResult.ListenConn listenConn := prepareResult.ListenConn
@ -298,30 +298,30 @@ func (sv *XTCPVisitor) makeNatHole() {
AssistedAddrs: prepareResult.AssistedAddrs, 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) natHoleRespMsg, err := nathole.ExchangeInfo(sv.ctx, sv.helper.MsgTransporter(), transactionID, natHoleVisitorMsg, 5*time.Second)
if err != nil { if err != nil {
listenConn.Close() listenConn.Close()
xl.Warn("nathole exchange info error: %v", err) xl.Warnf("nathole exchange info error: %v", err)
return 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.Sid, natHoleRespMsg.Protocol, natHoleRespMsg.CandidateAddrs,
natHoleRespMsg.AssistedAddrs, natHoleRespMsg.DetectBehavior) natHoleRespMsg.AssistedAddrs, natHoleRespMsg.DetectBehavior)
newListenConn, raddr, err := nathole.MakeHole(sv.ctx, listenConn, natHoleRespMsg, []byte(sv.cfg.SecretKey)) newListenConn, raddr, err := nathole.MakeHole(sv.ctx, listenConn, natHoleRespMsg, []byte(sv.cfg.SecretKey))
if err != nil { if err != nil {
listenConn.Close() listenConn.Close()
xl.Warn("make hole error: %v", err) xl.Warnf("make hole error: %v", err)
return return
} }
listenConn = newListenConn 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 { if err := sv.session.Init(listenConn, raddr); err != nil {
listenConn.Close() listenConn.Close()
xl.Warn("init tunnel session error: %v", err) xl.Warnf("init tunnel session error: %v", err)
return return
} }
} }

6
cmd/frpc/sub/root.go

@ -136,11 +136,11 @@ func startService(
visitorCfgs []v1.VisitorConfigurer, visitorCfgs []v1.VisitorConfigurer,
cfgFile string, cfgFile string,
) error { ) 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 != "" { if cfgFile != "" {
log.Info("start frpc service for config file [%s]", cfgFile) log.Infof("start frpc service for config file [%s]", cfgFile)
defer log.Info("frpc service for config file [%s] stopped", cfgFile) defer log.Infof("frpc service for config file [%s] stopped", cfgFile)
} }
svr, err := client.NewService(client.ServiceOptions{ svr, err := client.NewService(client.ServiceOptions{
Common: cfg, Common: cfg,

8
cmd/frps/root.go

@ -99,19 +99,19 @@ func Execute() {
} }
func runServer(cfg *v1.ServerConfig) (err error) { 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 != "" { if cfgFile != "" {
log.Info("frps uses config file: %s", cfgFile) log.Infof("frps uses config file: %s", cfgFile)
} else { } else {
log.Info("frps uses command line arguments for config") log.Infof("frps uses command line arguments for config")
} }
svr, err := server.NewService(cfg) svr, err := server.NewService(cfg)
if err != nil { if err != nil {
return err return err
} }
log.Info("frps started successfully") log.Infof("frps started successfully")
svr.Run(context.Background()) svr.Run(context.Background())
return return
} }

7
go.mod

@ -5,8 +5,7 @@ go 1.22
require ( require (
github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5 github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5
github.com/coreos/go-oidc/v3 v3.6.0 github.com/coreos/go-oidc/v3 v3.6.0
github.com/fatedier/beego v0.0.0-20171024143340-6c6a4f5bd5eb github.com/fatedier/golib v0.4.0
github.com/fatedier/golib v0.3.0
github.com/google/uuid v1.3.0 github.com/google/uuid v1.3.0
github.com/gorilla/mux v1.8.0 github.com/gorilla/mux v1.8.0
github.com/gorilla/websocket v1.5.0 github.com/gorilla/websocket v1.5.0
@ -25,7 +24,7 @@ require (
github.com/stretchr/testify v1.8.4 github.com/stretchr/testify v1.8.4
github.com/tidwall/gjson v1.17.1 github.com/tidwall/gjson v1.17.1
github.com/xtaci/kcp-go/v5 v5.6.7 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/net v0.19.0
golang.org/x/oauth2 v0.10.0 golang.org/x/oauth2 v0.10.0
golang.org/x/sync v0.3.0 golang.org/x/sync v0.3.0
@ -70,7 +69,7 @@ require (
go.uber.org/mock v0.3.0 // indirect go.uber.org/mock v0.3.0 // indirect
golang.org/x/exp v0.0.0-20221205204356-47842c84f3db // indirect golang.org/x/exp v0.0.0-20221205204356-47842c84f3db // indirect
golang.org/x/mod v0.11.0 // 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/text v0.14.0 // indirect
golang.org/x/tools v0.9.3 // indirect golang.org/x/tools v0.9.3 // indirect
google.golang.org/appengine v1.6.7 // indirect google.golang.org/appengine v1.6.7 // indirect

18
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.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4=
github.com/envoyproxy/go-control-plane v0.9.4/go.mod h1:6rpuAdCZL397s3pYoYcLgu1mIlRU8Am5FuJP05cCM98= 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/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/golib v0.4.0 h1:lafvYRMhFmqrfIUChKy/f5AXqs1eDSk+GAUtLexN5bU=
github.com/fatedier/beego v0.0.0-20171024143340-6c6a4f5bd5eb/go.mod h1:wx3gB6dbIfBRcucp94PI9Bt3I0F2c/MyNEWuhzpWiwk= github.com/fatedier/golib v0.4.0/go.mod h1:gpu+1vXxtJ072NYaNsn/YWgojDL8Ap2kFZQtbzT2qkg=
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/yamux v0.0.0-20230628132301-7aca4898904d h1:ynk1ra0RUqDWQfvFi5KtMiSobkVQ3cNc0ODb8CfIETo= 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/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= 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.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.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.12.0/go.mod h1:NF0Gs7EO5K4qLn+Ylc+fih8BSTeIjAP05siRnAh98yw=
golang.org/x/crypto v0.17.0 h1:r8bRNjWL3GshPW3gkd+RpvzWrZAwPS49OmTGZ/uhM4k= golang.org/x/crypto v0.18.0 h1:PGVlW0xEltQnzFZ55hkuX5+KLyrMYhHld1YHO4AKcdc=
golang.org/x/crypto v0.17.0/go.mod h1:gCAAfMLgwOJRpTjQ2zCCt2OcSfYMTeZVSRtQlPC7Nq4= 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-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 h1:D/cFflL63o2KSLJIwjlcIt8PR064j/xsmdEJL/YvY/o=
golang.org/x/exp v0.0.0-20221205204356-47842c84f3db/go.mod h1:CxIveKay+FTh1D0yPZemJVgC/95VzuuOLq5Qi4xnoYc= 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.7.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.8.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.11.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
golang.org/x/sys v0.15.0 h1:h48lPFYpsTvQJZF4EKyI4aLHaev3CxivZmv7yZig9pc= golang.org/x/sys v0.16.0 h1:xWw16ngr6ZMtmxDyKyIgsE93KNKz5HKmMa3b8ALHidU=
golang.org/x/sys v0.15.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= 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-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.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.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.7.0/go.mod h1:P32HKFT3hSsZrRxla30E9HqToFYAQPCMs/zFMBUFqPY=
golang.org/x/term v0.8.0/go.mod h1:xPskH00ivmX89bAKVGSKKtLOWNx2+17Eiy94tnKShWo= 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.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.16.0 h1:m+B6fahuftsE9qjo0VWp2FW0mB3MTJvR0BaMQrq0pmE=
golang.org/x/term v0.15.0/go.mod h1:BDl952bC7+uMoWR75FIrCDx79TPU9oHkTZ9yRbYOrX0= 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.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.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=

4
pkg/metrics/mem/server.go

@ -62,7 +62,7 @@ func (m *serverMetrics) run() {
time.Sleep(12 * time.Hour) time.Sleep(12 * time.Hour)
start := time.Now() start := time.Now()
count, total := m.clearUselessInfo(time.Duration(7*24) * time.Hour) 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 { time.Since(data.LastCloseTime) > continuousOfflineDuration {
delete(m.info.ProxyStatistics, name) delete(m.info.ProxyStatistics, name)
count++ 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 return count, total

22
pkg/nathole/controller.go

@ -115,7 +115,7 @@ func (c *Controller) CleanWorker(ctx context.Context) {
case <-ticker.C: case <-ticker.C:
start := time.Now() start := time.Now()
count, total := c.analyzer.Clean() 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(): case <-ctx.Done():
return return
} }
@ -191,11 +191,11 @@ func (c *Controller) HandleVisitor(m *msg.NatHoleVisitor, transporter transport.
return nil return nil
}() }()
if err != 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())) _ = transporter.Send(c.GenNatHoleResponse(m.TransactionID, nil, err.Error()))
return 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() { defer func() {
c.mu.Lock() c.mu.Lock()
@ -213,14 +213,14 @@ func (c *Controller) HandleVisitor(m *msg.NatHoleVisitor, transporter transport.
select { select {
case <-session.notifyCh: case <-session.notifyCh:
case <-time.After(time.Duration(NatHoleTimeout) * time.Second): 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 return
} }
// Make hole-punching decisions based on the NAT information of the client and visitor. // Make hole-punching decisions based on the NAT information of the client and visitor.
vResp, cResp, err := c.analysis(session) vResp, cResp, err := c.analysis(session)
if err != nil { 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()) vResp = c.GenNatHoleResponse(session.visitorMsg.TransactionID, nil, err.Error())
cResp = c.GenNatHoleResponse(session.clientMsg.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 { if !ok {
return 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.clientMsg = m
session.clientTransporter = transporter session.clientTransporter = transporter
select { select {
@ -271,13 +271,13 @@ func (c *Controller) HandleReport(m *msg.NatHoleReport) {
session, ok := c.sessions[m.Sid] session, ok := c.sessions[m.Sid]
c.mu.RUnlock() c.mu.RUnlock()
if !ok { 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 return
} }
if m.Success { if m.Success {
c.analyzer.ReportSuccess(session.analysisKey, session.recommandMode, session.recommandIndex) 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) 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) session.sid, *vNatFeature, vm.MappedAddrs, *cNatFeature, cm.MappedAddrs, protocol)
log.Debug("sid [%s] visitor detect behavior: %+v", session.sid, vResp.DetectBehavior) log.Debugf("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] client detect behavior: %+v", session.sid, cResp.DetectBehavior)
return vResp, cResp, nil return vResp, cResp, nil
} }

24
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++ { for i := 0; i < m.DetectBehavior.ListenRandomPorts; i++ {
tmpConn, err := net.ListenUDP("udp4", nil) tmpConn, err := net.ListenUDP("udp4", nil)
if err != nil { if err != nil {
xl.Warn("listen random udp addr error: %v", err) xl.Warnf("listen random udp addr error: %v", err)
continue continue
} }
listenConns = append(listenConns, tmpConn) listenConns = append(listenConns, tmpConn)
@ -216,7 +216,7 @@ func MakeHole(ctx context.Context, listenConn *net.UDPConn, m *msg.NatHoleResp,
for _, detectAddr := range detectAddrs { for _, detectAddr := range detectAddrs {
for _, conn := range listenConns { for _, conn := range listenConns {
if err := sendSidMessage(ctx, conn, m.Sid, transactionID, detectAddr, key, m.DetectBehavior.TTL); err != nil { 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 { if err != nil {
return nil, err 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 var m msg.NatHoleSid
if err := DecodeMessageInto(buf[:n], key, &m); err != nil { 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 continue
} }
pool.PutBuf(buf) pool.PutBuf(buf)
if m.Sid != sid { 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 continue
} }
@ -311,7 +311,7 @@ func waitDetectMessage(
m.Response = true m.Response = true
buf2, err := EncodeMessage(&m, key) buf2, err := EncodeMessage(&m, key)
if err != nil { if err != nil {
xl.Warn("encode sid message error: %v", err) xl.Warnf("encode sid message error: %v", err)
continue continue
} }
_, _ = conn.WriteToUDP(buf2, raddr) _, _ = conn.WriteToUDP(buf2, raddr)
@ -329,7 +329,7 @@ func sendSidMessage(
if ttl > 0 { if ttl > 0 {
ttlStr = fmt.Sprintf(" with ttl %d", ttl) 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) raddr, err := net.ResolveUDPAddr("udp4", addr)
if err != nil { if err != nil {
return err return err
@ -351,14 +351,14 @@ func sendSidMessage(
uConn := ipv4.NewConn(conn) uConn := ipv4.NewConn(conn)
original, err := uConn.TTL() original, err := uConn.TTL()
if err != nil { if err != nil {
xl.Trace("get ttl error %v", err) xl.Tracef("get ttl error %v", err)
return err return err
} }
xl.Trace("original ttl %d", original) xl.Tracef("original ttl %d", original)
err = uConn.SetTTL(ttl) err = uConn.SetTTL(ttl)
if err != nil { if err != nil {
xl.Trace("set ttl error %v", err) xl.Tracef("set ttl error %v", err)
} else { } else {
defer func() { defer func() {
_ = uConn.SetTTL(original) _ = uConn.SetTTL(original)
@ -382,7 +382,7 @@ func sendSidMessageToRangePorts(
for i := portsRange.From; i <= portsRange.To; i++ { for i := portsRange.From; i <= portsRange.To; i++ {
detectAddr := net.JoinHostPort(ip, strconv.Itoa(i)) detectAddr := net.JoinHostPort(ip, strconv.Itoa(i))
if err := sendFunc(conn, detectAddr); err != nil { 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) time.Sleep(2 * time.Millisecond)
} }
@ -422,7 +422,7 @@ func sendSidMessageToRandomPorts(
for _, ip := range slices.Compact(parseIPs(addrs)) { for _, ip := range slices.Compact(parseIPs(addrs)) {
detectAddr := net.JoinHostPort(ip, strconv.Itoa(port)) detectAddr := net.JoinHostPort(ip, strconv.Itoa(port))
if err := sendFunc(conn, detectAddr); err != nil { 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) time.Sleep(time.Millisecond * 15)
} }

12
pkg/plugin/server/manager.go

@ -86,7 +86,7 @@ func (m *Manager) Login(content *LoginContent) (*LoginContent, error) {
for _, p := range m.loginPlugins { for _, p := range m.loginPlugins {
res, retContent, err = p.Handle(ctx, OpLogin, *content) res, retContent, err = p.Handle(ctx, OpLogin, *content)
if err != nil { 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") return nil, errors.New("send Login request to plugin error")
} }
if res.Reject { if res.Reject {
@ -120,7 +120,7 @@ func (m *Manager) NewProxy(content *NewProxyContent) (*NewProxyContent, error) {
for _, p := range m.newProxyPlugins { for _, p := range m.newProxyPlugins {
res, retContent, err = p.Handle(ctx, OpNewProxy, *content) res, retContent, err = p.Handle(ctx, OpNewProxy, *content)
if err != nil { 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") return nil, errors.New("send NewProxy request to plugin error")
} }
if res.Reject { if res.Reject {
@ -147,7 +147,7 @@ func (m *Manager) CloseProxy(content *CloseProxyContent) error {
for _, p := range m.closeProxyPlugins { for _, p := range m.closeProxyPlugins {
_, _, err := p.Handle(ctx, OpCloseProxy, *content) _, _, err := p.Handle(ctx, OpCloseProxy, *content)
if err != nil { 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)) 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 { for _, p := range m.pingPlugins {
res, retContent, err = p.Handle(ctx, OpPing, *content) res, retContent, err = p.Handle(ctx, OpPing, *content)
if err != nil { 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") return nil, errors.New("send Ping request to plugin error")
} }
if res.Reject { if res.Reject {
@ -213,7 +213,7 @@ func (m *Manager) NewWorkConn(content *NewWorkConnContent) (*NewWorkConnContent,
for _, p := range m.newWorkConnPlugins { for _, p := range m.newWorkConnPlugins {
res, retContent, err = p.Handle(ctx, OpNewWorkConn, *content) res, retContent, err = p.Handle(ctx, OpNewWorkConn, *content)
if err != nil { 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") return nil, errors.New("send NewWorkConn request to plugin error")
} }
if res.Reject { if res.Reject {
@ -247,7 +247,7 @@ func (m *Manager) NewUserConn(content *NewUserConnContent) (*NewUserConnContent,
for _, p := range m.newUserConnPlugins { for _, p := range m.newUserConnPlugins {
res, retContent, err = p.Handle(ctx, OpNewUserConn, *content) res, retContent, err = p.Handle(ctx, OpNewUserConn, *content)
if err != nil { 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") return nil, errors.New("send NewUserConn request to plugin error")
} }
if res.Reject { if res.Reject {

4
pkg/ssh/gateway.go

@ -75,7 +75,7 @@ func NewGateway(
sshConfig.PublicKeyCallback = func(conn ssh.ConnMetadata, key ssh.PublicKey) (*ssh.Permissions, error) { sshConfig.PublicKeyCallback = func(conn ssh.ConnMetadata, key ssh.PublicKey) (*ssh.Permissions, error) {
authorizedKeysMap, err := loadAuthorizedKeysFromFile(cfg.AuthorizedKeysFile) authorizedKeysMap, err := loadAuthorizedKeysFromFile(cfg.AuthorizedKeysFile)
if err != nil { 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") return nil, fmt.Errorf("internal error")
} }
@ -120,7 +120,7 @@ func (g *Gateway) handleConn(conn net.Conn) {
return return
} }
if err := ts.Run(); err != nil { if err := ts.Run(); err != nil {
log.Error("ssh tunnel server run error: %v", err) log.Errorf("ssh tunnel server run error: %v", err)
} }
} }

6
pkg/ssh/server.go

@ -123,7 +123,7 @@ func (s *TunnelServer) Run() error {
// join workConn and ssh channel // join workConn and ssh channel
c, err := s.openConn(addr) c, err := s.openConn(addr)
if err != nil { if err != nil {
log.Trace("open conn error: %v", err) log.Tracef("open conn error: %v", err)
workConn.Close() workConn.Close()
return false return false
} }
@ -167,7 +167,7 @@ func (s *TunnelServer) Run() error {
if ps, err := s.waitProxyStatusReady(pc.GetBaseConfig().Name, time.Second); err != nil { if ps, err := s.waitProxyStatusReady(pc.GetBaseConfig().Name, time.Second); err != nil {
s.writeToClient(err.Error()) s.writeToClient(err.Error())
log.Warn("wait proxy status ready error: %v", err) log.Warnf("wait proxy status ready error: %v", err)
} else { } else {
// success // success
s.writeToClient(createSuccessInfo(clientCfg.User, pc, ps)) s.writeToClient(createSuccessInfo(clientCfg.User, pc, ps))
@ -175,7 +175,7 @@ func (s *TunnelServer) Run() error {
} }
s.vc.Close() 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() { s.closeDoneChOnce.Do(func() {
_ = sshConn.Close() _ = sshConn.Close()
close(s.doneCh) close(s.doneCh)

91
pkg/util/log/log.go

@ -15,78 +15,65 @@
package log package log
import ( import (
"fmt" "os"
"github.com/fatedier/beego/logs" "github.com/fatedier/golib/log"
) )
// Log is the under log object var Logger *log.Logger
var Log *logs.BeeLogger
func init() { func init() {
Log = logs.NewLogger(200) Logger = log.New(
Log.EnableFuncCallDepth(true) log.WithCaller(true),
Log.SetLogFuncCallDepth(Log.GetLogFuncCallDepth() + 1) log.AddCallerSkip(1),
log.WithLevel(log.InfoLevel),
)
} }
func InitLog(logFile string, logLevel string, maxdays int64, disableLogColor bool) { func InitLogger(logPath string, levelStr string, maxDays int, disableLogColor bool) {
SetLogFile(logFile, maxdays, disableLogColor) options := []log.Option{}
SetLogLevel(logLevel) if logPath == "console" {
} if !disableLogColor {
options = append(options,
// SetLogFile to configure log params log.WithOutput(log.NewConsoleWriter(log.ConsoleConfig{
func SetLogFile(logFile string, maxdays int64, disableLogColor bool) { Colorful: true,
if logFile == "console" { }, os.Stdout)),
params := "" )
if disableLogColor {
params = `{"color": false}`
} }
_ = Log.SetLogger("console", params)
} else { } else {
params := fmt.Sprintf(`{"filename": "%s", "maxdays": %d}`, logFile, maxdays) writer := log.NewRotateFileWriter(log.RotateFileConfig{
_ = Log.SetLogger("file", params) FileName: logPath,
Mode: log.RotateFileModeDaily,
MaxDays: maxDays,
})
writer.Init()
options = append(options, log.WithOutput(writer))
} }
}
// SetLogLevel set log level, default is warning level, err := log.ParseLevel(levelStr)
// value: error, warning, info, debug, trace if err != nil {
func SetLogLevel(logLevel string) { level = log.InfoLevel
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
} }
Log.SetLevel(level) options = append(options, log.WithLevel(level))
Logger = Logger.WithOptions(options...)
} }
// wrap log func Errorf(format string, v ...interface{}) {
Logger.Errorf(format, v...)
func Error(format string, v ...interface{}) {
Log.Error(format, v...)
} }
func Warn(format string, v ...interface{}) { func Warnf(format string, v ...interface{}) {
Log.Warn(format, v...) Logger.Warnf(format, v...)
} }
func Info(format string, v ...interface{}) { func Infof(format string, v ...interface{}) {
Log.Info(format, v...) Logger.Infof(format, v...)
} }
func Debug(format string, v ...interface{}) { func Debugf(format string, v ...interface{}) {
Log.Debug(format, v...) Logger.Debugf(format, v...)
} }
func Trace(format string, v ...interface{}) { func Tracef(format string, v ...interface{}) {
Log.Trace(format, v...) Logger.Tracef(format, v...)
} }

14
pkg/util/vhost/http.go

@ -20,7 +20,7 @@ import (
"encoding/base64" "encoding/base64"
"errors" "errors"
"fmt" "fmt"
"log" stdlog "log"
"net" "net"
"net/http" "net/http"
"net/http/httputil" "net/http/httputil"
@ -32,7 +32,7 @@ import (
"github.com/fatedier/golib/pool" "github.com/fatedier/golib/pool"
httppkg "github.com/fatedier/frp/pkg/util/http" 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") 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 // ignore error here, it will use CreateConnFn instead later
endpoint, _ = rc.ChooseEndpointFn() endpoint, _ = rc.ChooseEndpointFn()
reqRouteInfo.Endpoint = endpoint 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) endpoint, oldHost, reqRouteInfo.URL, reqRouteInfo.HTTPUser)
} }
// Set {domain}.{location}.{routeByHTTPUser}.{endpoint} as URL host here to let http transport reuse connections. // 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(), BufferPool: newWrapPool(),
ErrorLog: log.New(newWrapLogger(), "", 0), ErrorLog: stdlog.New(newWrapLogger(), "", 0),
ErrorHandler: func(rw http.ResponseWriter, req *http.Request, err error) { 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.WriteHeader(http.StatusNotFound)
_, _ = rw.Write(getNotFoundPageContent()) _, _ = rw.Write(getNotFoundPageContent())
}, },
@ -145,7 +145,7 @@ func (rp *HTTPReverseProxy) UnRegister(routeCfg RouteConfig) {
func (rp *HTTPReverseProxy) GetRouteConfig(domain, location, routeByHTTPUser string) *RouteConfig { func (rp *HTTPReverseProxy) GetRouteConfig(domain, location, routeByHTTPUser string) *RouteConfig {
vr, ok := rp.getVhost(domain, location, routeByHTTPUser) vr, ok := rp.getVhost(domain, location, routeByHTTPUser)
if ok { 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 vr.payload.(*RouteConfig)
} }
return nil return nil
@ -335,6 +335,6 @@ type wrapLogger struct{}
func newWrapLogger() *wrapLogger { return &wrapLogger{} } func newWrapLogger() *wrapLogger { return &wrapLogger{} }
func (l *wrapLogger) Write(p []byte) (n int, err error) { 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 return len(p), nil
} }

4
pkg/util/vhost/resource.go

@ -20,7 +20,7 @@ import (
"net/http" "net/http"
"os" "os"
logpkg "github.com/fatedier/frp/pkg/util/log" "github.com/fatedier/frp/pkg/util/log"
"github.com/fatedier/frp/pkg/util/version" "github.com/fatedier/frp/pkg/util/version"
) )
@ -58,7 +58,7 @@ func getNotFoundPageContent() []byte {
if NotFoundPagePath != "" { if NotFoundPagePath != "" {
buf, err = os.ReadFile(NotFoundPagePath) buf, err = os.ReadFile(NotFoundPagePath)
if err != nil { if err != nil {
logpkg.Warn("read custom 404 page error: %v", err) log.Warnf("read custom 404 page error: %v", err)
buf = []byte(NotFound) buf = []byte(NotFound)
} }
} else { } else {

16
pkg/util/vhost/vhost.go

@ -203,7 +203,7 @@ func (v *Muxer) handle(c net.Conn) {
sConn, reqInfoMap, err := v.vhostFunc(c) sConn, reqInfoMap, err := v.vhostFunc(c)
if err != nil { 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() _ = c.Close()
return return
} }
@ -213,7 +213,7 @@ func (v *Muxer) handle(c net.Conn) {
httpUser := reqInfoMap["HTTPUser"] httpUser := reqInfoMap["HTTPUser"]
l, ok := v.getListener(name, path, httpUser) l, ok := v.getListener(name, path, httpUser)
if !ok { 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) v.failHook(sConn)
return return
} }
@ -221,7 +221,7 @@ func (v *Muxer) handle(c net.Conn) {
xl := xlog.FromContextSafe(l.ctx) xl := xlog.FromContextSafe(l.ctx)
if v.successHook != nil { if v.successHook != nil {
if err := v.successHook(c, reqInfoMap); err != 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() _ = c.Close()
return return
} }
@ -232,7 +232,7 @@ func (v *Muxer) handle(c net.Conn) {
if l.mux.checkAuth != nil && l.username != "" { if l.mux.checkAuth != nil && l.username != "" {
ok, err := l.mux.checkAuth(c, l.username, l.password, reqInfoMap) ok, err := l.mux.checkAuth(c, l.username, l.password, reqInfoMap)
if !ok || err != nil { if !ok || err != nil {
xl.Debug("auth failed for user: %s", l.username) xl.Debugf("auth failed for user: %s", l.username)
_ = c.Close() _ = c.Close()
return return
} }
@ -244,12 +244,12 @@ func (v *Muxer) handle(c net.Conn) {
} }
c = sConn 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() { err = errors.PanicToError(func() {
l.accept <- c l.accept <- c
}) })
if err != nil { 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 { if l.mux.rewriteHost != nil {
sConn, err := l.mux.rewriteHost(conn, l.rewriteHost) sConn, err := l.mux.rewriteHost(conn, l.rewriteHost)
if err != nil { 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") 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 conn = sConn
} }
return netpkg.NewContextConn(l.ctx, conn), nil return netpkg.NewContextConn(l.ctx, conn), nil

20
pkg/util/xlog/xlog.go

@ -94,22 +94,22 @@ func (l *Logger) Spawn() *Logger {
return nl return nl
} }
func (l *Logger) Error(format string, v ...interface{}) { func (l *Logger) Errorf(format string, v ...interface{}) {
log.Log.Error(l.prefixString+format, v...) log.Logger.Errorf(l.prefixString+format, v...)
} }
func (l *Logger) Warn(format string, v ...interface{}) { func (l *Logger) Warnf(format string, v ...interface{}) {
log.Log.Warn(l.prefixString+format, v...) log.Logger.Warnf(l.prefixString+format, v...)
} }
func (l *Logger) Info(format string, v ...interface{}) { func (l *Logger) Infof(format string, v ...interface{}) {
log.Log.Info(l.prefixString+format, v...) log.Logger.Infof(l.prefixString+format, v...)
} }
func (l *Logger) Debug(format string, v ...interface{}) { func (l *Logger) Debugf(format string, v ...interface{}) {
log.Log.Debug(l.prefixString+format, v...) log.Logger.Debugf(l.prefixString+format, v...)
} }
func (l *Logger) Trace(format string, v ...interface{}) { func (l *Logger) Tracef(format string, v ...interface{}) {
log.Log.Trace(l.prefixString+format, v...) log.Logger.Tracef(l.prefixString+format, v...)
} }

34
server/control.go

@ -224,7 +224,7 @@ func (ctl *Control) Close() error {
func (ctl *Control) Replaced(newCtl *Control) { func (ctl *Control) Replaced(newCtl *Control) {
xl := ctl.xl xl := ctl.xl
xl.Info("Replaced by client [%s]", newCtl.runID) xl.Infof("Replaced by client [%s]", newCtl.runID)
ctl.runID = "" ctl.runID = ""
ctl.conn.Close() ctl.conn.Close()
} }
@ -233,17 +233,17 @@ func (ctl *Control) RegisterWorkConn(conn net.Conn) error {
xl := ctl.xl xl := ctl.xl
defer func() { defer func() {
if err := recover(); err != nil { if err := recover(); err != nil {
xl.Error("panic error: %v", err) xl.Errorf("panic error: %v", err)
xl.Error(string(debug.Stack())) xl.Errorf(string(debug.Stack()))
} }
}() }()
select { select {
case ctl.workConnCh <- conn: case ctl.workConnCh <- conn:
xl.Debug("new work connection registered") xl.Debugf("new work connection registered")
return nil return nil
default: 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") 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 xl := ctl.xl
defer func() { defer func() {
if err := recover(); err != nil { if err := recover(); err != nil {
xl.Error("panic error: %v", err) xl.Errorf("panic error: %v", err)
xl.Error(string(debug.Stack())) xl.Errorf(string(debug.Stack()))
} }
}() }()
@ -269,7 +269,7 @@ func (ctl *Control) GetWorkConn() (workConn net.Conn, err error) {
err = pkgerr.ErrCtlClosed err = pkgerr.ErrCtlClosed
return return
} }
xl.Debug("get work connection from pool") xl.Debugf("get work connection from pool")
default: default:
// no work connections available in the poll, send message to frpc to get more // no work connections available in the poll, send message to frpc to get more
if err := ctl.msgDispatcher.Send(&msg.ReqWorkConn{}); err != nil { 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: case workConn, ok = <-ctl.workConnCh:
if !ok { if !ok {
err = pkgerr.ErrCtlClosed err = pkgerr.ErrCtlClosed
xl.Warn("no work connections available, %v", err) xl.Warnf("no work connections available, %v", err)
return return
} }
case <-time.After(time.Duration(ctl.serverCfg.UserConnTimeout) * time.Second): case <-time.After(time.Duration(ctl.serverCfg.UserConnTimeout) * time.Second):
err = fmt.Errorf("timeout trying to get work connection") err = fmt.Errorf("timeout trying to get work connection")
xl.Warn("%v", err) xl.Warnf("%v", err)
return return
} }
} }
@ -305,7 +305,7 @@ func (ctl *Control) heartbeatWorker() {
if !lo.FromPtr(ctl.serverCfg.Transport.TCPMux) && ctl.serverCfg.Transport.HeartbeatTimeout > 0 { if !lo.FromPtr(ctl.serverCfg.Transport.TCPMux) && ctl.serverCfg.Transport.HeartbeatTimeout > 0 {
go wait.Until(func() { go wait.Until(func() {
if time.Since(ctl.lastPing.Load().(time.Time)) > time.Duration(ctl.serverCfg.Transport.HeartbeatTimeout)*time.Second { 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() ctl.conn.Close()
return return
} }
@ -356,7 +356,7 @@ func (ctl *Control) worker() {
} }
metrics.Server.CloseClient() metrics.Server.CloseClient()
xl.Info("client exit success") xl.Infof("client exit success")
close(ctl.doneCh) close(ctl.doneCh)
} }
@ -393,12 +393,12 @@ func (ctl *Control) handleNewProxy(m msg.Message) {
ProxyName: inMsg.ProxyName, ProxyName: inMsg.ProxyName,
} }
if err != nil { 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), resp.Error = util.GenerateResponseErrorString(fmt.Sprintf("new proxy [%s] error", inMsg.ProxyName),
err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient)) err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient))
} else { } else {
resp.RemoteAddr = remoteAddr 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) metrics.Server.NewProxy(inMsg.ProxyName, inMsg.ProxyType)
} }
_ = ctl.msgDispatcher.Send(resp) _ = ctl.msgDispatcher.Send(resp)
@ -422,14 +422,14 @@ func (ctl *Control) handlePing(m msg.Message) {
err = ctl.authVerifier.VerifyPing(inMsg) err = ctl.authVerifier.VerifyPing(inMsg)
} }
if err != nil { if err != nil {
xl.Warn("received invalid ping: %v", err) xl.Warnf("received invalid ping: %v", err)
_ = ctl.msgDispatcher.Send(&msg.Pong{ _ = ctl.msgDispatcher.Send(&msg.Pong{
Error: util.GenerateResponseErrorString("invalid ping", err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient)), Error: util.GenerateResponseErrorString("invalid ping", err, lo.FromPtr(ctl.serverCfg.DetailedErrorsToClient)),
}) })
return return
} }
ctl.lastPing.Store(time.Now()) ctl.lastPing.Store(time.Now())
xl.Debug("receive heartbeat") xl.Debugf("receive heartbeat")
_ = ctl.msgDispatcher.Send(&msg.Pong{}) _ = ctl.msgDispatcher.Send(&msg.Pong{})
} }
@ -452,7 +452,7 @@ func (ctl *Control) handleCloseProxy(m msg.Message) {
xl := ctl.xl xl := ctl.xl
inMsg := m.(*msg.CloseProxy) inMsg := m.(*msg.CloseProxy)
_ = ctl.CloseProxy(inMsg) _ = 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) { func (ctl *Control) RegisterProxy(pxyMsg *msg.NewProxy) (remoteAddr string, err error) {

30
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) { func (svr *Service) apiServerInfo(w http.ResponseWriter, r *http.Request) {
res := GeneralResponse{Code: 200} res := GeneralResponse{Code: 200}
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = 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() serverStats := mem.StatsCollector.GetServer()
svrResp := serverInfoResp{ svrResp := serverInfoResp{
Version: version.Full(), Version: version.Full(),
@ -219,13 +219,13 @@ func (svr *Service) apiProxyByType(w http.ResponseWriter, r *http.Request) {
proxyType := params["type"] proxyType := params["type"]
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
} }
}() }()
log.Info("Http request: [%s]", r.URL.Path) log.Infof("Http request: [%s]", r.URL.Path)
proxyInfoResp := GetProxyInfoResp{} proxyInfoResp := GetProxyInfoResp{}
proxyInfoResp.Proxies = svr.getProxyStatsByType(proxyType) 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 { if pxy, ok := svr.pxyManager.GetByName(ps.Name); ok {
content, err := json.Marshal(pxy.GetConfigurer()) content, err := json.Marshal(pxy.GetConfigurer())
if err != nil { 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 continue
} }
proxyInfo.Conf = getConfByType(ps.Type) proxyInfo.Conf = getConfByType(ps.Type)
if err = json.Unmarshal(content, &proxyInfo.Conf); err != nil { 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 continue
} }
proxyInfo.Status = "online" proxyInfo.Status = "online"
@ -291,13 +291,13 @@ func (svr *Service) apiProxyByTypeAndName(w http.ResponseWriter, r *http.Request
name := params["name"] name := params["name"]
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
} }
}() }()
log.Info("Http request: [%s]", r.URL.Path) log.Infof("Http request: [%s]", r.URL.Path)
var proxyStatsResp GetProxyStatsResp var proxyStatsResp GetProxyStatsResp
proxyStatsResp, res.Code, res.Msg = svr.getProxyStatsByTypeAndName(proxyType, name) 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 { if pxy, ok := svr.pxyManager.GetByName(proxyName); ok {
content, err := json.Marshal(pxy.GetConfigurer()) content, err := json.Marshal(pxy.GetConfigurer())
if err != nil { 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 code = 400
msg = "parse conf error" msg = "parse conf error"
return return
} }
proxyInfo.Conf = getConfByType(ps.Type) proxyInfo.Conf = getConfByType(ps.Type)
if err = json.Unmarshal(content, &proxyInfo.Conf); err != nil { 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 code = 400
msg = "parse conf error" msg = "parse conf error"
return return
@ -359,13 +359,13 @@ func (svr *Service) apiProxyTraffic(w http.ResponseWriter, r *http.Request) {
name := params["name"] name := params["name"]
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
} }
}() }()
log.Info("Http request: [%s]", r.URL.Path) log.Infof("Http request: [%s]", r.URL.Path)
trafficResp := GetProxyTrafficResp{} trafficResp := GetProxyTrafficResp{}
trafficResp.Name = name 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) { func (svr *Service) deleteProxies(w http.ResponseWriter, r *http.Request) {
res := GeneralResponse{Code: 200} res := GeneralResponse{Code: 200}
log.Info("Http request: [%s]", r.URL.Path) log.Infof("Http request: [%s]", r.URL.Path)
defer func() { 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) w.WriteHeader(res.Code)
if len(res.Msg) > 0 { if len(res.Msg) > 0 {
_, _ = w.Write([]byte(res.Msg)) _, _ = w.Write([]byte(res.Msg))
@ -403,5 +403,5 @@ func (svr *Service) deleteProxies(w http.ResponseWriter, r *http.Request) {
return return
} }
cleared, total := mem.StatsCollector.ClearOfflineProxies() 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)
} }

8
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)) 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) 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)) 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) 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 xl := pxy.xl
rAddr, errRet := net.ResolveTCPAddr("tcp", remoteAddr) rAddr, errRet := net.ResolveTCPAddr("tcp", remoteAddr)
if errRet != nil { 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 // 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 { if pxy.cfg.Transport.UseEncryption {
rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token)) rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return return
} }
} }

4
server/proxy/https.go

@ -64,7 +64,7 @@ func (pxy *HTTPSProxy) Run() (remoteAddr string, err error) {
err = errRet err = errRet
return 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) pxy.listeners = append(pxy.listeners, l)
addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort)) addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort))
} }
@ -76,7 +76,7 @@ func (pxy *HTTPSProxy) Run() (remoteAddr string, err error) {
err = errRet err = errRet
return 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) pxy.listeners = append(pxy.listeners, l)
addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort)) addrs = append(addrs, util.CanonicalAddr(routeConfig.Domain, pxy.serverCfg.VhostHTTPSPort))
} }

26
server/proxy/proxy.go

@ -112,7 +112,7 @@ func (pxy *BaseProxy) GetConfigurer() v1.ProxyConfigurer {
func (pxy *BaseProxy) Close() { func (pxy *BaseProxy) Close() {
xl := xlog.FromContextSafe(pxy.ctx) xl := xlog.FromContextSafe(pxy.ctx)
xl.Info("proxy closing") xl.Infof("proxy closing")
for _, l := range pxy.listeners { for _, l := range pxy.listeners {
l.Close() l.Close()
} }
@ -125,10 +125,10 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn,
// try all connections from the pool // try all connections from the pool
for i := 0; i < pxy.poolCount+1; i++ { for i := 0; i < pxy.poolCount+1; i++ {
if workConn, err = pxy.getWorkConnFn(); err != nil { 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 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()) xl.Spawn().AppendPrefix(pxy.GetName())
workConn = netpkg.NewContextConn(pxy.ctx, workConn) workConn = netpkg.NewContextConn(pxy.ctx, workConn)
@ -158,7 +158,7 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn,
Error: "", Error: "",
}) })
if err != nil { 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() workConn.Close()
} else { } else {
break break
@ -166,7 +166,7 @@ func (pxy *BaseProxy) GetWorkConnFromPool(src, dst net.Addr) (workConn net.Conn,
} }
if err != nil { 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
} }
return return
@ -193,15 +193,15 @@ func (pxy *BaseProxy) startCommonTCPListenersHandler() {
if max := 1 * time.Second; tempDelay > max { if max := 1 * time.Second; tempDelay > max {
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) time.Sleep(tempDelay)
continue continue
} }
xl.Warn("listener is closed: %s", err) xl.Warnf("listener is closed: %s", err)
return 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) go pxy.handleUserTCPConnection(c)
} }
}(listener) }(listener)
@ -225,7 +225,7 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) {
} }
_, err := rc.PluginManager.NewUserConn(content) _, err := rc.PluginManager.NewUserConn(content)
if err != nil { 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 return
} }
@ -237,12 +237,12 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) {
defer workConn.Close() defer workConn.Close()
var local io.ReadWriteCloser = workConn 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) cfg.Transport.UseEncryption, cfg.Transport.UseCompression)
if cfg.Transport.UseEncryption { if cfg.Transport.UseEncryption {
local, err = libio.WithEncryption(local, []byte(serverCfg.Auth.Token)) local, err = libio.WithEncryption(local, []byte(serverCfg.Auth.Token))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
return 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()) workConn.RemoteAddr().String(), userConn.LocalAddr().String(), userConn.RemoteAddr().String())
name := pxy.GetName() name := pxy.GetName()
@ -268,7 +268,7 @@ func (pxy *BaseProxy) handleUserTCPConnection(userConn net.Conn) {
metrics.Server.CloseConnection(name, proxyType) metrics.Server.CloseConnection(name, proxyType)
metrics.Server.AddTrafficIn(name, proxyType, inCount) metrics.Server.AddTrafficIn(name, proxyType, inCount)
metrics.Server.AddTrafficOut(name, proxyType, outCount) metrics.Server.AddTrafficOut(name, proxyType, outCount)
xl.Debug("join connections closed") xl.Debugf("join connections closed")
} }
type Options struct { type Options struct {

2
server/proxy/stcp.go

@ -53,7 +53,7 @@ func (pxy *STCPProxy) Run() (remoteAddr string, err error) {
return return
} }
pxy.listeners = append(pxy.listeners, listener) pxy.listeners = append(pxy.listeners, listener)
xl.Info("stcp proxy custom listen success") xl.Infof("stcp proxy custom listen success")
pxy.startCommonTCPListenersHandler() pxy.startCommonTCPListenersHandler()
return return

2
server/proxy/sudp.go

@ -53,7 +53,7 @@ func (pxy *SUDPProxy) Run() (remoteAddr string, err error) {
return return
} }
pxy.listeners = append(pxy.listeners, listener) pxy.listeners = append(pxy.listeners, listener)
xl.Info("sudp proxy custom listen success") xl.Infof("sudp proxy custom listen success")
pxy.startCommonTCPListenersHandler() pxy.startCommonTCPListenersHandler()
return return

4
server/proxy/tcp.go

@ -62,7 +62,7 @@ func (pxy *TCPProxy) Run() (remoteAddr string, err error) {
}() }()
pxy.realBindPort = realBindPort pxy.realBindPort = realBindPort
pxy.listeners = append(pxy.listeners, l) 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 { } else {
pxy.realBindPort, err = pxy.rc.TCPPortManager.Acquire(pxy.name, pxy.cfg.RemotePort) pxy.realBindPort, err = pxy.rc.TCPPortManager.Acquire(pxy.name, pxy.cfg.RemotePort)
if err != nil { if err != nil {
@ -79,7 +79,7 @@ func (pxy *TCPProxy) Run() (remoteAddr string, err error) {
return return
} }
pxy.listeners = append(pxy.listeners, listener) 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 pxy.cfg.RemotePort = pxy.realBindPort

2
server/proxy/tcpmux.go

@ -65,7 +65,7 @@ func (pxy *TCPMuxProxy) httpConnectListen(
if err != nil { if err != nil {
return nil, err 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) domain, pxy.cfg.LoadBalancer.Group, pxy.cfg.RouteByHTTPUser)
pxy.listeners = append(pxy.listeners, l) pxy.listeners = append(pxy.listeners, l)
return append(addrs, util.CanonicalAddr(domain, pxy.serverCfg.TCPMuxHTTPConnectPort)), nil return append(addrs, util.CanonicalAddr(domain, pxy.serverCfg.TCPMuxHTTPConnectPort)), nil

26
server/proxy/udp.go

@ -97,10 +97,10 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
udpConn, errRet := net.ListenUDP("udp", addr) udpConn, errRet := net.ListenUDP("udp", addr)
if errRet != nil { if errRet != nil {
err = errRet err = errRet
xl.Warn("listen udp port error: %v", err) xl.Warnf("listen udp port error: %v", err)
return 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.udpConn = udpConn
pxy.sendCh = make(chan *msg.UDPPacket, 1024) pxy.sendCh = make(chan *msg.UDPPacket, 1024)
@ -114,11 +114,11 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
rawMsg msg.Message rawMsg msg.Message
errRet error 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 // client will send heartbeat in workConn for keeping alive
_ = conn.SetReadDeadline(time.Now().Add(time.Duration(60) * time.Second)) _ = conn.SetReadDeadline(time.Now().Add(time.Duration(60) * time.Second))
if rawMsg, errRet = msg.ReadMsg(conn); errRet != nil { 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() _ = conn.Close()
// notify proxy to start a new work connection // notify proxy to start a new work connection
// ignore error here, it means the proxy is closed // ignore error here, it means the proxy is closed
@ -128,15 +128,15 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
return return
} }
if err := conn.SetReadDeadline(time.Time{}); err != nil { 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) { switch m := rawMsg.(type) {
case *msg.Ping: case *msg.Ping:
xl.Trace("udp work conn get ping message") xl.Tracef("udp work conn get ping message")
continue continue
case *msg.UDPPacket: case *msg.UDPPacket:
if errRet := errors.PanicToError(func() { 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 pxy.readCh <- m
metrics.Server.AddTrafficOut( metrics.Server.AddTrafficOut(
pxy.GetName(), pxy.GetName(),
@ -145,7 +145,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
) )
}); errRet != nil { }); errRet != nil {
conn.Close() conn.Close()
xl.Info("reader goroutine for udp work connection closed") xl.Infof("reader goroutine for udp work connection closed")
return return
} }
} }
@ -159,15 +159,15 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
select { select {
case udpMsg, ok := <-pxy.sendCh: case udpMsg, ok := <-pxy.sendCh:
if !ok { if !ok {
xl.Info("sender goroutine for udp work connection closed") xl.Infof("sender goroutine for udp work connection closed")
return return
} }
if errRet = msg.WriteMsg(conn, udpMsg); errRet != nil { 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() conn.Close()
return return
} }
xl.Trace("send message to udp workConn: %s", udpMsg.Content) xl.Tracef("send message to udp workConn: %s", udpMsg.Content)
metrics.Server.AddTrafficIn( metrics.Server.AddTrafficIn(
pxy.GetName(), pxy.GetName(),
pxy.GetConfigurer().GetBaseConfig().Type, pxy.GetConfigurer().GetBaseConfig().Type,
@ -175,7 +175,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
) )
continue continue
case <-ctx.Done(): case <-ctx.Done():
xl.Info("sender goroutine for udp work connection closed") xl.Infof("sender goroutine for udp work connection closed")
return return
} }
} }
@ -207,7 +207,7 @@ func (pxy *UDPProxy) Run() (remoteAddr string, err error) {
if pxy.cfg.Transport.UseEncryption { if pxy.cfg.Transport.UseEncryption {
rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token)) rwc, err = libio.WithEncryption(rwc, []byte(pxy.serverCfg.Auth.Token))
if err != nil { if err != nil {
xl.Error("create encryption stream error: %v", err) xl.Errorf("create encryption stream error: %v", err)
workConn.Close() workConn.Close()
continue continue
} }

2
server/proxy/xtcp.go

@ -77,7 +77,7 @@ func (pxy *XTCPProxy) Run() (remoteAddr string, err error) {
} }
errRet = msg.WriteMsg(workConn, m) errRet = msg.WriteMsg(workConn, m)
if errRet != nil { 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() workConn.Close()
} }

52
server/service.go

@ -172,13 +172,13 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
if err != nil { if err != nil {
return nil, fmt.Errorf("create vhost tcpMuxer error, %v", err) 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 // Init all plugins
for _, p := range cfg.HTTPPlugins { for _, p := range cfg.HTTPPlugins {
svr.pluginManager.Register(plugin.NewHTTPPluginOptions(p)) 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 svr.rc.PluginManager = svr.pluginManager
@ -222,7 +222,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
ln = svr.muxer.DefaultListener() ln = svr.muxer.DefaultListener()
svr.listener = ln 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. // Listen for accepting connections from client using kcp protocol.
if cfg.KCPBindPort > 0 { if cfg.KCPBindPort > 0 {
@ -231,7 +231,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
if err != nil { if err != nil {
return nil, fmt.Errorf("listen on kcp udp address %s error: %v", address, err) 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 { if cfg.QUICBindPort > 0 {
@ -246,7 +246,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
if err != nil { if err != nil {
return nil, fmt.Errorf("listen on quic udp address %s error: %v", address, err) 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 { 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) return nil, fmt.Errorf("create ssh gateway error: %v", err)
} }
svr.sshTunnelGateway = sshGateway 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. // Listen for accepting connections from client using websocket protocol.
@ -289,7 +289,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
go func() { go func() {
_ = server.Serve(l) _ = server.Serve(l)
}() }()
log.Info("http service listen on %s", address) log.Infof("http service listen on %s", address)
} }
// Create https vhost muxer. // Create https vhost muxer.
@ -303,7 +303,7 @@ func NewService(cfg *v1.ServerConfig) (*Service, error) {
if err != nil { if err != nil {
return nil, fmt.Errorf("create server listener error, %v", err) 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) svr.rc.VhostHTTPSMuxer, err = vhost.NewHTTPSMuxer(l, vhostReadWriteTimeout)
@ -335,9 +335,9 @@ func (svr *Service) Run(ctx context.Context) {
// run dashboard web server. // run dashboard web server.
if svr.webServer != nil { if svr.webServer != nil {
go func() { 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 { 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)) _ = conn.SetReadDeadline(time.Now().Add(connReadTimeout))
if rawMsg, err = msg.ReadMsg(conn); err != nil { 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() conn.Close()
return return
} }
@ -430,7 +430,7 @@ func (svr *Service) handleConnection(ctx context.Context, conn net.Conn, interna
// If login failed, send error message there. // If login failed, send error message there.
// Otherwise send success message in control's work goroutine. // Otherwise send success message in control's work goroutine.
if err != nil { if err != nil {
xl.Warn("register control error: %v", err) xl.Warnf("register control error: %v", err)
_ = msg.WriteMsg(conn, &msg.LoginResp{ _ = msg.WriteMsg(conn, &msg.LoginResp{
Version: version.Full(), Version: version.Full(),
Error: util.GenerateResponseErrorString("register control error", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), 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: case *msg.NewVisitorConn:
if err = svr.RegisterVisitorConn(conn, m); err != nil { 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{ _ = msg.WriteMsg(conn, &msg.NewVisitorConnResp{
ProxyName: m.ProxyName, ProxyName: m.ProxyName,
Error: util.GenerateResponseErrorString("register visitor conn error", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), 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: 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() conn.Close()
} }
} }
@ -469,7 +469,7 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) {
for { for {
c, err := l.Accept() c, err := l.Accept()
if err != nil { if err != nil {
log.Warn("Listener for incoming connections from client closed") log.Warnf("Listener for incoming connections from client closed")
return return
} }
// inject xlog object into net.Conn context // 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) c = netpkg.NewContextConn(xlog.NewContext(ctx, xl), c)
if !internal { if !internal {
log.Trace("start check TLS connection...") log.Tracef("start check TLS connection...")
originConn := c originConn := c
forceTLS := svr.cfg.Transport.TLS.Force forceTLS := svr.cfg.Transport.TLS.Force
var isTLS, custom bool var isTLS, custom bool
c, isTLS, custom, err = netpkg.CheckAndEnableTLSServerConnWithTimeout(c, svr.tlsConfig, forceTLS, connReadTimeout) c, isTLS, custom, err = netpkg.CheckAndEnableTLSServerConnWithTimeout(c, svr.tlsConfig, forceTLS, connReadTimeout)
if err != nil { if err != nil {
log.Warn("CheckAndEnableTLSServerConnWithTimeout error: %v", err) log.Warnf("CheckAndEnableTLSServerConnWithTimeout error: %v", err)
originConn.Close() originConn.Close()
continue 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. // 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 fmuxCfg.MaxStreamWindowSize = 6 * 1024 * 1024
session, err := fmux.Server(frpConn, fmuxCfg) session, err := fmux.Server(frpConn, fmuxCfg)
if err != nil { if err != nil {
log.Warn("Failed to create mux connection: %v", err) log.Warnf("Failed to create mux connection: %v", err)
frpConn.Close() frpConn.Close()
return return
} }
@ -509,7 +509,7 @@ func (svr *Service) HandleListener(l net.Listener, internal bool) {
for { for {
stream, err := session.AcceptStream() stream, err := session.AcceptStream()
if err != nil { if err != nil {
log.Debug("Accept new mux stream error: %v", err) log.Debugf("Accept new mux stream error: %v", err)
session.Close() session.Close()
return return
} }
@ -527,7 +527,7 @@ func (svr *Service) HandleQUICListener(l *quic.Listener) {
for { for {
c, err := l.Accept(context.Background()) c, err := l.Accept(context.Background())
if err != nil { if err != nil {
log.Warn("QUICListener for incoming connections from client closed") log.Warnf("QUICListener for incoming connections from client closed")
return return
} }
// Start a new goroutine to handle connection. // Start a new goroutine to handle connection.
@ -535,7 +535,7 @@ func (svr *Service) HandleQUICListener(l *quic.Listener) {
for { for {
stream, err := frpConn.AcceptStream(context.Background()) stream, err := frpConn.AcceptStream(context.Background())
if err != nil { 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, "") _ = frpConn.CloseWithError(0, "")
return return
} }
@ -560,7 +560,7 @@ func (svr *Service) RegisterControl(ctlConn net.Conn, loginMsg *msg.Login, inter
xl := xlog.FromContextSafe(ctx) xl := xlog.FromContextSafe(ctx)
xl.AppendPrefix(loginMsg.RunID) xl.AppendPrefix(loginMsg.RunID)
ctx = xlog.NewContext(ctx, xl) 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) ctlConn.RemoteAddr().String(), loginMsg.Version, loginMsg.Hostname, loginMsg.Os, loginMsg.Arch)
// Check auth. // Check auth.
@ -575,7 +575,7 @@ func (svr *Service) RegisterControl(ctlConn net.Conn, loginMsg *msg.Login, inter
// TODO(fatedier): use SessionContext // TODO(fatedier): use SessionContext
ctl, err := NewControl(ctx, svr.rc, svr.pxyManager, svr.pluginManager, authVerifier, ctlConn, !internal, loginMsg, svr.cfg) ctl, err := NewControl(ctx, svr.rc, svr.pxyManager, svr.pluginManager, authVerifier, ctlConn, !internal, loginMsg, svr.cfg)
if err != nil { 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 // don't return detailed errors to client
return fmt.Errorf("unexpected error when creating new controller") 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) xl := netpkg.NewLogFromConn(workConn)
ctl, exist := svr.ctlManager.GetByID(newMsg.RunID) ctl, exist := svr.ctlManager.GetByID(newMsg.RunID)
if !exist { 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) return fmt.Errorf("no client control found for run id [%s]", newMsg.RunID)
} }
// server plugin hook // server plugin hook
@ -620,7 +620,7 @@ func (svr *Service) RegisterWorkConn(workConn net.Conn, newMsg *msg.NewWorkConn)
err = ctl.authVerifier.VerifyNewWorkConn(newMsg) err = ctl.authVerifier.VerifyNewWorkConn(newMsg)
} }
if err != nil { 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{ _ = msg.WriteMsg(workConn, &msg.StartWorkConn{
Error: util.GenerateResponseErrorString("invalid NewWorkConn", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)), Error: util.GenerateResponseErrorString("invalid NewWorkConn", err, lo.FromPtr(svr.cfg.DetailedErrorsToClient)),
}) })

2
test/e2e/e2e.go

@ -38,7 +38,7 @@ func RunE2ETests(t *testing.T) {
// Randomize specs as well as suites // Randomize specs as well as suites
suiteConfig.RandomizeAllSpecs = true 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) framework.RunID, suiteConfig.ParallelProcess, suiteConfig.ParallelTotal)
ginkgo.RunSpecs(t, "frp e2e suite", suiteConfig, reporterConfig) ginkgo.RunSpecs(t, "frp e2e suite", suiteConfig, reporterConfig)
} }

2
test/e2e/e2e_test.go

@ -34,7 +34,7 @@ func TestMain(m *testing.M) {
os.Exit(1) os.Exit(1)
} }
log.InitLog("console", framework.TestContext.LogLevel, 0, true) log.InitLogger("console", framework.TestContext.LogLevel, 0, true)
os.Exit(m.Run()) os.Exit(m.Run())
} }

4
test/e2e/framework/process.go

@ -31,7 +31,7 @@ func (f *Framework) RunProcesses(serverTemplates []string, clientTemplates []str
ExpectNoError(err) ExpectNoError(err)
if TestContext.Debug { 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) p := process.NewWithEnvs(TestContext.FRPServerPath, []string{"-c", path}, f.osEnvs)
@ -52,7 +52,7 @@ func (f *Framework) RunProcesses(serverTemplates []string, clientTemplates []str
ExpectNoError(err) ExpectNoError(err)
if TestContext.Debug { 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) p := process.NewWithEnvs(TestContext.FRPClientPath, []string{"-c", path}, f.osEnvs)

6
test/e2e/framework/request.go

@ -20,7 +20,7 @@ func ExpectResponseCode(code int) EnsureFunc {
if resp.Code == code { if resp.Code == code {
return true 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 return false
} }
} }
@ -111,14 +111,14 @@ func (e *RequestExpect) Ensure(fns ...EnsureFunc) {
if len(fns) == 0 { if len(fns) == 0 {
if !bytes.Equal(e.expectResp, ret.Content) { 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...) ExpectEqualValuesWithOffset(1, ret.Content, e.expectResp, e.explain...)
} else { } else {
for _, fn := range fns { for _, fn := range fns {
ok := fn(ret) ok := fn(ret)
if !ok { if !ok {
flog.Trace("Response info: %+v", ret) flog.Tracef("Response info: %+v", ret)
} }
ExpectTrueWithOffset(1, ok, e.explain...) ExpectTrueWithOffset(1, ok, e.explain...)
} }

2
test/e2e/legacy/features/monitor.go

@ -41,7 +41,7 @@ var _ = ginkgo.Describe("[Feature: Monitor]", func() {
framework.NewRequestExpect(f).RequestModify(func(r *request.Request) { framework.NewRequestExpect(f).RequestModify(func(r *request.Request) {
r.HTTP().Port(dashboardPort).HTTPPath("/metrics") r.HTTP().Port(dashboardPort).HTTPPath("/metrics")
}).Ensure(func(resp *request.Response) bool { }).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 { if resp.Code != 200 {
return false return false
} }

8
test/e2e/legacy/features/real_ip.go

@ -66,7 +66,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
rd := bufio.NewReader(c) rd := bufio.NewReader(c)
ppHeader, err := pp.Read(rd) ppHeader, err := pp.Read(rd)
if err != nil { if err != nil {
log.Error("read proxy protocol error: %v", err) log.Errorf("read proxy protocol error: %v", err)
return return
} }
@ -93,7 +93,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
f.RunProcesses([]string{serverConf}, []string{clientConf}) f.RunProcesses([]string{serverConf}, []string{clientConf})
framework.NewRequestExpect(f).Port(remotePort).Ensure(func(resp *request.Response) bool { 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)) addr, err := net.ResolveTCPAddr("tcp", string(resp.Content))
if err != nil { if err != nil {
return false return false
@ -121,7 +121,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
rd := bufio.NewReader(c) rd := bufio.NewReader(c)
ppHeader, err := pp.Read(rd) ppHeader, err := pp.Read(rd)
if err != nil { if err != nil {
log.Error("read proxy protocol error: %v", err) log.Errorf("read proxy protocol error: %v", err)
return return
} }
srcAddrRecord = ppHeader.SourceAddr.String() srcAddrRecord = ppHeader.SourceAddr.String()
@ -142,7 +142,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
r.HTTP().HTTPHost("normal.example.com") r.HTTP().HTTPHost("normal.example.com")
}).Ensure(framework.ExpectResponseCode(404)) }).Ensure(framework.ExpectResponseCode(404))
log.Trace("ProxyProtocol get SourceAddr: %s", srcAddrRecord) log.Tracef("ProxyProtocol get SourceAddr: %s", srcAddrRecord)
addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord) addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord)
framework.ExpectNoError(err, srcAddrRecord) framework.ExpectNoError(err, srcAddrRecord)
framework.ExpectEqualValues("127.0.0.1", addr.IP.String()) framework.ExpectEqualValues("127.0.0.1", addr.IP.String())

4
test/e2e/pkg/plugin/plugin.go

@ -26,7 +26,7 @@ func NewHTTPPluginServer(port int, newFunc NewPluginRequest, handler Handler, tl
w.WriteHeader(500) w.WriteHeader(500)
return return
} }
log.Trace("plugin request: %s", string(buf)) log.Tracef("plugin request: %s", string(buf))
err = json.Unmarshal(buf, &r) err = json.Unmarshal(buf, &r)
if err != nil { if err != nil {
w.WriteHeader(500) w.WriteHeader(500)
@ -34,7 +34,7 @@ func NewHTTPPluginServer(port int, newFunc NewPluginRequest, handler Handler, tl
} }
resp := handler(r) resp := handler(r)
buf, _ = json.Marshal(resp) buf, _ = json.Marshal(resp)
log.Trace("plugin response: %s", string(buf)) log.Tracef("plugin response: %s", string(buf))
_, _ = w.Write(buf) _, _ = w.Write(buf)
})), })),
) )

2
test/e2e/v1/features/monitor.go

@ -42,7 +42,7 @@ var _ = ginkgo.Describe("[Feature: Monitor]", func() {
framework.NewRequestExpect(f).RequestModify(func(r *request.Request) { framework.NewRequestExpect(f).RequestModify(func(r *request.Request) {
r.HTTP().Port(dashboardPort).HTTPPath("/metrics") r.HTTP().Port(dashboardPort).HTTPPath("/metrics")
}).Ensure(func(resp *request.Response) bool { }).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 { if resp.Code != 200 {
return false return false
} }

8
test/e2e/v1/features/real_ip.go

@ -67,7 +67,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
rd := bufio.NewReader(c) rd := bufio.NewReader(c)
ppHeader, err := pp.Read(rd) ppHeader, err := pp.Read(rd)
if err != nil { if err != nil {
log.Error("read proxy protocol error: %v", err) log.Errorf("read proxy protocol error: %v", err)
return return
} }
@ -95,7 +95,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
f.RunProcesses([]string{serverConf}, []string{clientConf}) f.RunProcesses([]string{serverConf}, []string{clientConf})
framework.NewRequestExpect(f).Port(remotePort).Ensure(func(resp *request.Response) bool { 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)) addr, err := net.ResolveTCPAddr("tcp", string(resp.Content))
if err != nil { if err != nil {
return false return false
@ -123,7 +123,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
rd := bufio.NewReader(c) rd := bufio.NewReader(c)
ppHeader, err := pp.Read(rd) ppHeader, err := pp.Read(rd)
if err != nil { if err != nil {
log.Error("read proxy protocol error: %v", err) log.Errorf("read proxy protocol error: %v", err)
return return
} }
srcAddrRecord = ppHeader.SourceAddr.String() srcAddrRecord = ppHeader.SourceAddr.String()
@ -145,7 +145,7 @@ var _ = ginkgo.Describe("[Feature: Real IP]", func() {
r.HTTP().HTTPHost("normal.example.com") r.HTTP().HTTPHost("normal.example.com")
}).Ensure(framework.ExpectResponseCode(404)) }).Ensure(framework.ExpectResponseCode(404))
log.Trace("ProxyProtocol get SourceAddr: %s", srcAddrRecord) log.Tracef("ProxyProtocol get SourceAddr: %s", srcAddrRecord)
addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord) addr, err := net.ResolveTCPAddr("tcp", srcAddrRecord)
framework.ExpectNoError(err, srcAddrRecord) framework.ExpectNoError(err, srcAddrRecord)
framework.ExpectEqualValues("127.0.0.1", addr.IP.String()) framework.ExpectEqualValues("127.0.0.1", addr.IP.String())

Loading…
Cancel
Save