From a1023fdfc29198e30d4b522e8020c8873c9f7cb4 Mon Sep 17 00:00:00 2001 From: fatedier Date: Sun, 12 Mar 2017 02:03:24 +0800 Subject: [PATCH] add more log --- client/control.go | 107 ++++++++++++++++++++++++++----------------- client/proxy.go | 14 ++++-- server/control.go | 4 +- server/proxy.go | 5 ++ utils/log/log.go | 17 +++++-- utils/net/conn.go | 1 + utils/net/tcp.go | 2 + utils/net/udp.go | 9 ++-- utils/vhost/vhost.go | 17 +++++-- 9 files changed, 115 insertions(+), 61 deletions(-) diff --git a/client/control.go b/client/control.go index 0b0b8f6b..d81b18eb 100644 --- a/client/control.go +++ b/client/control.go @@ -281,18 +281,21 @@ func (ctl *Control) manager() { ctl.Warn("[%s] start error: %s", m.ProxyName, m.Error) continue } - oldPxy, ok := ctl.proxies[m.ProxyName] - if ok { - oldPxy.Close() - } cfg, ok := ctl.pxyCfgs[m.ProxyName] if !ok { // it will never go to this branch ctl.Warn("[%s] no proxy conf found", m.ProxyName) continue } + oldPxy, ok := ctl.proxies[m.ProxyName] + if ok { + oldPxy.Close() + } pxy := NewProxy(ctl, cfg) - pxy.Run() + if err := pxy.Run(); err != nil { + ctl.Warn("[%s] proxy start running error: %v", m.ProxyName, err) + continue + } ctl.proxies[m.ProxyName] = pxy ctl.Info("[%s] start proxy success", m.ProxyName) case *msg.Pong: @@ -307,46 +310,64 @@ func (ctl *Control) controler() { var err error maxDelayTime := 30 * time.Second delayTime := time.Second + + checkInterval := 60 * time.Second + checkProxyTicker := time.NewTicker(checkInterval) for { - // we won't get any variable from this channel - _, ok := <-ctl.closedCh - if !ok { - // close related channels - close(ctl.readCh) - close(ctl.sendCh) - time.Sleep(time.Second) - - // loop util reconnect to server success - for { - ctl.Info("try to reconnect to server...") - err = ctl.login() - if err != nil { - ctl.Warn("reconnect to server error: %v", err) - time.Sleep(delayTime) - delayTime = delayTime * 2 - if delayTime > maxDelayTime { - delayTime = maxDelayTime - } - continue - } - // reconnect success, init the delayTime - delayTime = time.Second - break - } - - // init related channels and variables - ctl.init() - - // previous work goroutines should be closed and start them here - go ctl.manager() - go ctl.writer() - go ctl.reader() - - // send NewProxy message for all configured proxies + select { + case <-checkProxyTicker.C: + // Every 60 seconds, check which proxy registered failed and reregister it to server. for _, cfg := range ctl.pxyCfgs { - var newProxyMsg msg.NewProxy - cfg.UnMarshalToMsg(&newProxyMsg) - ctl.sendCh <- &newProxyMsg + if _, exist := ctl.proxies[cfg.GetName()]; !exist { + ctl.Info("try to reregister proxy [%s]", cfg.GetName()) + var newProxyMsg msg.NewProxy + cfg.UnMarshalToMsg(&newProxyMsg) + ctl.sendCh <- &newProxyMsg + } + } + case _, ok := <-ctl.closedCh: + // we won't get any variable from this channel + if !ok { + // close related channels + close(ctl.readCh) + close(ctl.sendCh) + time.Sleep(time.Second) + + // loop util reconnect to server success + for { + ctl.Info("try to reconnect to server...") + err = ctl.login() + if err != nil { + ctl.Warn("reconnect to server error: %v", err) + time.Sleep(delayTime) + delayTime = delayTime * 2 + if delayTime > maxDelayTime { + delayTime = maxDelayTime + } + continue + } + // reconnect success, init the delayTime + delayTime = time.Second + break + } + + // init related channels and variables + ctl.init() + + // previous work goroutines should be closed and start them here + go ctl.manager() + go ctl.writer() + go ctl.reader() + + // send NewProxy message for all configured proxies + for _, cfg := range ctl.pxyCfgs { + var newProxyMsg msg.NewProxy + cfg.UnMarshalToMsg(&newProxyMsg) + ctl.sendCh <- &newProxyMsg + } + + checkProxyTicker.Stop() + checkProxyTicker = time.NewTicker(checkInterval) } } } diff --git a/client/proxy.go b/client/proxy.go index 317c134c..fd916996 100644 --- a/client/proxy.go +++ b/client/proxy.go @@ -25,7 +25,7 @@ import ( // Proxy defines how to work for different proxy type. type Proxy interface { - Run() + Run() error // InWorkConn accept work connections registered to server. InWorkConn(conn net.Conn) @@ -64,7 +64,8 @@ type TcpProxy struct { ctl *Control } -func (pxy *TcpProxy) Run() { +func (pxy *TcpProxy) Run() (err error) { + return } func (pxy *TcpProxy) Close() { @@ -81,7 +82,8 @@ type HttpProxy struct { ctl *Control } -func (pxy *HttpProxy) Run() { +func (pxy *HttpProxy) Run() (err error) { + return } func (pxy *HttpProxy) Close() { @@ -98,7 +100,8 @@ type HttpsProxy struct { ctl *Control } -func (pxy *HttpsProxy) Run() { +func (pxy *HttpsProxy) Run() (err error) { + return } func (pxy *HttpsProxy) Close() { @@ -115,7 +118,8 @@ type UdpProxy struct { ctl *Control } -func (pxy *UdpProxy) Run() { +func (pxy *UdpProxy) Run() (err error) { + return } func (pxy *UdpProxy) Close() { diff --git a/server/control.go b/server/control.go index 50a48cd0..6f47edd5 100644 --- a/server/control.go +++ b/server/control.go @@ -108,9 +108,9 @@ func (ctl *Control) RegisterWorkConn(conn net.Conn) { select { case ctl.workConnCh <- conn: - ctl.conn.Debug("new work connection registered.") + ctl.conn.Debug("new work connection registered") default: - ctl.conn.Debug("work connection pool is full, discarding.") + ctl.conn.Debug("work connection pool is full, discarding") conn.Close() } } diff --git a/server/proxy.go b/server/proxy.go index 4516d8a8..ac175796 100644 --- a/server/proxy.go +++ b/server/proxy.go @@ -109,6 +109,7 @@ func (pxy *TcpProxy) Run() error { if err != nil { return err } + listener.AddLogPrefix(pxy.name) pxy.listeners = append(pxy.listeners, listener) pxy.Info("tcp proxy listen port [%d]", pxy.cfg.RemotePort) @@ -148,6 +149,7 @@ func (pxy *HttpProxy) Run() (err error) { if err != nil { return err } + l.AddLogPrefix(pxy.name) pxy.Info("http proxy listen for host [%s] location [%s]", routeConfig.Domain, routeConfig.Location) pxy.listeners = append(pxy.listeners, l) } @@ -161,6 +163,7 @@ func (pxy *HttpProxy) Run() (err error) { if err != nil { return err } + l.AddLogPrefix(pxy.name) pxy.Info("http proxy listen for host [%s] location [%s]", routeConfig.Domain, routeConfig.Location) pxy.listeners = append(pxy.listeners, l) } @@ -192,6 +195,7 @@ func (pxy *HttpsProxy) Run() (err error) { if err != nil { return err } + l.AddLogPrefix(pxy.name) pxy.Info("https proxy listen for host [%s]", routeConfig.Domain) pxy.listeners = append(pxy.listeners, l) } @@ -202,6 +206,7 @@ func (pxy *HttpsProxy) Run() (err error) { if err != nil { return err } + l.AddLogPrefix(pxy.name) pxy.Info("https proxy listen for host [%s]", routeConfig.Domain) pxy.listeners = append(pxy.listeners, l) } diff --git a/utils/log/log.go b/utils/log/log.go index 1682ec7c..95192210 100644 --- a/utils/log/log.go +++ b/utils/log/log.go @@ -82,6 +82,7 @@ func Debug(format string, v ...interface{}) { // Logger type Logger interface { AddLogPrefix(string) + GetAllPrefix() []string ClearLogPrefix() Error(string, ...interface{}) Warn(string, ...interface{}) @@ -90,11 +91,14 @@ type Logger interface { } type PrefixLogger struct { - prefix string + prefix string + allPrefix []string } func NewPrefixLogger(prefix string) *PrefixLogger { - logger := &PrefixLogger{} + logger := &PrefixLogger{ + allPrefix: make([]string, 0), + } logger.AddLogPrefix(prefix) return logger } @@ -104,14 +108,17 @@ func (pl *PrefixLogger) AddLogPrefix(prefix string) { return } - if len(pl.prefix) > 0 { - pl.prefix += " " - } pl.prefix += "[" + prefix + "] " + pl.allPrefix = append(pl.allPrefix, prefix) +} + +func (pl *PrefixLogger) GetAllPrefix() []string { + return pl.allPrefix } func (pl *PrefixLogger) ClearLogPrefix() { pl.prefix = "" + pl.allPrefix = make([]string, 0) } func (pl *PrefixLogger) Error(format string, v ...interface{}) { diff --git a/utils/net/conn.go b/utils/net/conn.go index 129aab04..0189fdfd 100644 --- a/utils/net/conn.go +++ b/utils/net/conn.go @@ -29,4 +29,5 @@ type Conn interface { type Listener interface { Accept() (Conn, error) Close() error + log.Logger } diff --git a/utils/net/tcp.go b/utils/net/tcp.go index 67b560ff..7412b5dc 100644 --- a/utils/net/tcp.go +++ b/utils/net/tcp.go @@ -30,6 +30,7 @@ type TcpListener struct { listener net.Listener accept chan Conn closeFlag bool + log.Logger } func ListenTcp(bindAddr string, bindPort int64) (l *TcpListener, err error) { @@ -47,6 +48,7 @@ func ListenTcp(bindAddr string, bindPort int64) (l *TcpListener, err error) { listener: listener, accept: make(chan Conn), closeFlag: false, + Logger: log.NewPrefixLogger(""), } go func() { diff --git a/utils/net/udp.go b/utils/net/udp.go index 31e8b84b..b9ae0a57 100644 --- a/utils/net/udp.go +++ b/utils/net/udp.go @@ -21,7 +21,7 @@ import ( "sync" "time" - flog "github.com/fatedier/frp/utils/log" + "github.com/fatedier/frp/utils/log" "github.com/fatedier/frp/utils/pool" ) @@ -32,7 +32,7 @@ type UdpPacket struct { } type FakeUdpConn struct { - flog.Logger + log.Logger l *UdpListener localAddr net.Addr @@ -46,7 +46,7 @@ type FakeUdpConn struct { func NewFakeUdpConn(l *UdpListener, laddr, raddr net.Addr) *FakeUdpConn { fc := &FakeUdpConn{ - Logger: flog.NewPrefixLogger(""), + Logger: log.NewPrefixLogger(""), l: l, localAddr: laddr, remoteAddr: raddr, @@ -163,6 +163,8 @@ type UdpListener struct { closeFlag bool fakeConns map[string]*FakeUdpConn + + log.Logger } func ListenUDP(bindAddr string, bindPort int64) (l *UdpListener, err error) { @@ -177,6 +179,7 @@ func ListenUDP(bindAddr string, bindPort int64) (l *UdpListener, err error) { accept: make(chan Conn), writeCh: make(chan *UdpPacket, 1000), fakeConns: make(map[string]*FakeUdpConn), + Logger: log.NewPrefixLogger(""), } // for reading diff --git a/utils/vhost/vhost.go b/utils/vhost/vhost.go index 65424e85..5653a2b6 100644 --- a/utils/vhost/vhost.go +++ b/utils/vhost/vhost.go @@ -20,6 +20,7 @@ import ( "sync" "time" + "github.com/fatedier/frp/utils/log" frpNet "github.com/fatedier/frp/utils/net" ) @@ -77,6 +78,7 @@ func (v *VhostMuxer) Listen(cfg *VhostRouteConfig) (l *Listener, err error) { passWord: cfg.Password, mux: v, accept: make(chan frpNet.Conn), + Logger: log.NewPrefixLogger(""), } v.registryRouter.Add(cfg.Domain, cfg.Location, l) return l, nil @@ -126,6 +128,7 @@ func (v *VhostMuxer) handle(c frpNet.Conn) { sConn, reqInfoMap, err := v.vhostFunc(c) if err != nil { + log.Error("get hostname from http/https request error: %v", err) c.Close() return } @@ -134,16 +137,17 @@ func (v *VhostMuxer) handle(c frpNet.Conn) { path := strings.ToLower(reqInfoMap["Path"]) l, ok := v.getListener(name, path) if !ok { + log.Debug("http request for host [%s] path [%s] not found", name, path) c.Close() return } // if authFunc is exist and userName/password is set // verify user access - if l.mux.authFunc != nil && - l.userName != "" && l.passWord != "" { + if l.mux.authFunc != nil && l.userName != "" && l.passWord != "" { bAccess, err := l.mux.authFunc(c, l.userName, l.passWord, reqInfoMap["Authorization"]) if bAccess == false || err != nil { + l.Debug("check Authorization failed") res := noAuthResponse() res.Write(c) c.Close() @@ -157,6 +161,7 @@ func (v *VhostMuxer) handle(c frpNet.Conn) { } c = sConn + l.Debug("get new http request host [%s] path [%s]", name, path) l.accept <- c } @@ -168,6 +173,7 @@ type Listener struct { passWord string mux *VhostMuxer // for closing VhostMuxer accept chan frpNet.Conn + log.Logger } func (l *Listener) Accept() (frpNet.Conn, error) { @@ -181,11 +187,16 @@ func (l *Listener) Accept() (frpNet.Conn, error) { if l.mux.rewriteFunc != nil && l.rewriteHost != "" { sConn, err := l.mux.rewriteFunc(conn, l.rewriteHost) if err != nil { - return nil, fmt.Errorf("http host header rewrite failed") + l.Warn("host header rewrite failed: %v", err) + return nil, fmt.Errorf("host header rewrite failed") } + l.Debug("rewrite host to [%s] success", l.rewriteHost) conn = sConn } + for _, prefix := range l.GetAllPrefix() { + conn.AddLogPrefix(prefix) + } return conn, nil }