From ae700d457563d70cc997bf8de8db80f81d358f39 Mon Sep 17 00:00:00 2001 From: Sir Darkrengarius Date: Mon, 2 Mar 2020 13:53:47 +0300 Subject: [PATCH] Refactor debug logs --- cmd/apps/skychat/chat.go | 2 -- internal/skysocks/client.go | 1 - internal/skysocks/server.go | 6 ++-- pkg/app/conn.go | 8 ------ pkg/router/route_group.go | 2 +- pkg/router/router.go | 45 ++++++++++-------------------- pkg/transport/managed_transport.go | 28 ++++++++----------- pkg/transport/manager.go | 17 ++++++----- 8 files changed, 39 insertions(+), 70 deletions(-) diff --git a/cmd/apps/skychat/chat.go b/cmd/apps/skychat/chat.go index 55c293d57e..f53e86a6d2 100644 --- a/cmd/apps/skychat/chat.go +++ b/cmd/apps/skychat/chat.go @@ -148,8 +148,6 @@ func messageHandler(w http.ResponseWriter, req *http.Request) { conn, ok := chatConns[pk] connsMu.Unlock() - log.Printf("CHAT CONN IS %v\n", ok) - if !ok { var err error err = r.Do(func() error { diff --git a/internal/skysocks/client.go b/internal/skysocks/client.go index a27768a7b9..ec042c6d91 100644 --- a/internal/skysocks/client.go +++ b/internal/skysocks/client.go @@ -114,7 +114,6 @@ func (c *Client) handleStream(conn, stream net.Conn) { go func() { _, err := io.Copy(conn, stream) - Log.WithError(err).Error("GOT ERROR FROM STREAM OF APP CONN") errCh <- err }() diff --git a/internal/skysocks/server.go b/internal/skysocks/server.go index 0994341c05..8a90c1d275 100644 --- a/internal/skysocks/server.go +++ b/internal/skysocks/server.go @@ -46,16 +46,16 @@ func (s *Server) Serve(l net.Listener) error { conn, err := l.Accept() if err != nil { if s.isClosed() { - s.log.Errorf("GOT PROXY ACCEPT ERR %v, BUT SERVER IS CLOSED", err) + s.log.WithError(err).Debugln("Failed to accept skysocks connection, but server is closed") return nil } - s.log.Errorf("PROXY ACCEPT ERROR: %v", err) + s.log.WithError(err).Debugln("Failed to accept skysocks connection") return fmt.Errorf("accept: %s", err) } - s.log.Infoln("ACCEPTED NEW SKYSOCKS CONN") + s.log.Infoln("Accepted new skysocks connection") sessionCfg := yamux.DefaultConfig() sessionCfg.EnableKeepAlive = false diff --git a/pkg/app/conn.go b/pkg/app/conn.go index f190c284e7..ee70225b9e 100644 --- a/pkg/app/conn.go +++ b/pkg/app/conn.go @@ -24,15 +24,7 @@ type Conn struct { // Read reads from connection. func (c *Conn) Read(b []byte) (int, error) { - fmt.Println("LOCKIN ON READ APP CLIENT CONN") n, err := c.rpc.Read(c.id, b) - if err == io.EOF { - fmt.Println("EOF READING FROM APP CONN") - } - /*if err != nil && err != io.EOF { - fmt.Printf("READ ERROR: %v\n", err) - return n, &net.OpError{Op: "read", Net: c.local.Network(), Source: c.local, Addr: c.remote, Err: err} - }*/ return n, err } diff --git a/pkg/router/route_group.go b/pkg/router/route_group.go index c24e4cf478..87a209284a 100644 --- a/pkg/router/route_group.go +++ b/pkg/router/route_group.go @@ -268,7 +268,7 @@ func (rg *RouteGroup) read(p []byte) (int, error) { func (rg *RouteGroup) write(data []byte, tp *transport.ManagedTransport, rule routing.Rule) (int, error) { packet := routing.MakeDataPacket(rule.NextRouteID(), data) - rg.logger.Infof("WRITING PACKET OF TYPE %s AND ROUTE ID %d AND NEXT ID %d", packet.Type(), + rg.logger.Debugf("Writing packet of type %s, route ID %d and next ID %d", packet.Type(), rule.KeyRouteID(), rule.NextRouteID()) ctx, cancel := context.WithCancel(context.Background()) diff --git a/pkg/router/router.go b/pkg/router/router.go index 0e781ec3c0..1a2ae97308 100644 --- a/pkg/router/router.go +++ b/pkg/router/router.go @@ -326,38 +326,26 @@ func (r *router) saveRouteGroupRules(rules routing.EdgeRules) *RouteGroup { defer r.mx.Unlock() rg, ok := r.rgs[rules.Desc] - if !ok || rg == nil { - r.logger.Infof("Creating new route group rule with desc: %s", &rules.Desc) - rg = NewRouteGroup(DefaultRouteGroupConfig(), r.rt, rules.Desc) - r.rgs[rules.Desc] = rg - - rg.fwd = append(rg.fwd, rules.Forward) - rg.rvs = append(rg.rvs, rules.Reverse) - - tp := r.tm.Transport(rules.Forward.NextTransportID()) - rg.tps = append(rg.tps, tp) - } else { - r.logger.Infoln("ROUTE GROUP ALREADY EXISTS") + if ok && rg != nil { + r.logger.Infof("Route group with desc %s already exists, closing the old one and replacing...", &rules.Desc) if err := rg.Close(); err != nil { r.logger.Errorf("Error closing already existing route group: %v", err) } - rg = NewRouteGroup(DefaultRouteGroupConfig(), r.rt, rules.Desc) - r.rgs[rules.Desc] = rg + r.logger.Infoln("Successfully closed old route group") + } - rg.fwd = append(rg.fwd, rules.Forward) - rg.rvs = append(rg.rvs, rules.Reverse) + r.logger.Infof("Creating new route group rule with desc: %s", &rules.Desc) - tp := r.tm.Transport(rules.Forward.NextTransportID()) - rg.tps = append(rg.tps, tp) - } + rg = NewRouteGroup(DefaultRouteGroupConfig(), r.rt, rules.Desc) + r.rgs[rules.Desc] = rg - /*rg.fwd = append(rg.fwd, rules.Forward) + rg.fwd = append(rg.fwd, rules.Forward) rg.rvs = append(rg.rvs, rules.Reverse) tp := r.tm.Transport(rules.Forward.NextTransportID()) - rg.tps = append(rg.tps, tp)*/ + rg.tps = append(rg.tps, tp) return rg } @@ -382,10 +370,9 @@ func (r *router) handleDataPacket(ctx context.Context, packet routing.Packet) er } if rule.Type() == routing.RuleConsume { - r.logger.Infof("HANDLING PACKET OF TYPE %s WITH ROUTE ID %d", packet.Type(), - packet.RouteID()) + r.logger.Debugf("Handling packet of type %s with route ID %d", packet.Type(), packet.RouteID()) } else { - r.logger.Infof("HANDLING PACKET OF TYPE %s WITH ROUTE ID %d AND NEXT ID %d", packet.Type(), + r.logger.Debugf("Handling packet of type %s with route ID %d and next ID %d", packet.Type(), packet.RouteID(), rule.NextRouteID()) } @@ -426,10 +413,9 @@ func (r *router) handleClosePacket(ctx context.Context, packet routing.Packet) e } if rule.Type() == routing.RuleConsume { - r.logger.Infof("HANDLING PACKET OF TYPE %s WITH ROUTE ID %d", packet.Type(), - packet.RouteID()) + r.logger.Debugf("Handling packet of type %s with route ID %d", packet.Type(), packet.RouteID()) } else { - r.logger.Infof("HANDLING PACKET OF TYPE %s WITH ROUTE ID %d AND NEXT ID %d", packet.Type(), + r.logger.Debugf("Handling packet of type %s with route ID %d and next ID %d", packet.Type(), packet.RouteID(), rule.NextRouteID()) } @@ -487,10 +473,9 @@ func (r *router) handleKeepAlivePacket(ctx context.Context, packet routing.Packe } if rule.Type() == routing.RuleConsume { - r.logger.Infof("HANDLING PACKET OF TYPE %S WITH ROUTE ID %d", packet.Type(), - packet.RouteID()) + r.logger.Debugf("Handling packet of type %s with route ID %d", packet.Type(), packet.RouteID()) } else { - r.logger.Infof("HANDLING PACKET OF TYPE %S WITH ROUTE ID %d AND NEXT ID %d", packet.Type(), + r.logger.Debugf("Handling packet of type %s with route ID %d and next ID %d", packet.Type(), packet.RouteID(), rule.NextRouteID()) } diff --git a/pkg/transport/managed_transport.go b/pkg/transport/managed_transport.go index edb3e9940d..a32d36365f 100644 --- a/pkg/transport/managed_transport.go +++ b/pkg/transport/managed_transport.go @@ -118,10 +118,9 @@ func (mt *ManagedTransport) Serve(readCh chan<- routing.Packet, done <-chan stru }() for { p, err := mt.readPacket() - mt.log.Infof("GOT FROM TP: %s, err: %v", p, err) if err != nil { if err == ErrNotServing { - fmt.Println("NOT SERVING IN READ LOOP") + mt.log.WithError(err).Debugf("Failed to read packet") return } mt.connMx.Lock() @@ -201,14 +200,11 @@ func (mt *ManagedTransport) Accept(ctx context.Context, conn *snet.Conn) error { defer mt.connMx.Unlock() if conn.Network() != mt.netName { - mt.log.Infoln("WRONG NETWORK") return errors.New("wrong network") // TODO: Make global var. } - mt.log.Infoln("NETWORK OK") - if !mt.isServing() { - mt.log.Infoln("MT NOT SERVING") + mt.log.Debugln(ErrNotServing.Error()) if err := conn.Close(); err != nil { log.WithError(err).Warn("Failed to close connection") } @@ -217,12 +213,12 @@ func (mt *ManagedTransport) Accept(ctx context.Context, conn *snet.Conn) error { ctx, cancel := context.WithTimeout(ctx, time.Second*20) defer cancel() - mt.log.Infoln("PERFOMING HANDSHAKE...") + mt.log.Debugln("Performing handshake...") if err := MakeSettlementHS(false).Do(ctx, mt.dc, conn, mt.n.LocalSK()); err != nil { return fmt.Errorf("settlement handshake failed: %v", err) } - mt.log.Infoln("SETTING TP CONN...") + mt.log.Debugln("Setting TP conn...") return mt.setIfConnNil(ctx, conn) } @@ -299,7 +295,7 @@ func (mt *ManagedTransport) getConn() *snet.Conn { // TODO: Add logging here. func (mt *ManagedTransport) setIfConnNil(ctx context.Context, conn *snet.Conn) error { if mt.conn != nil { - mt.log.Infoln("CONN ALREADY EXISTS") + mt.log.Debugln("TP conn already exists, closing it") if err := conn.Close(); err != nil { log.WithError(err).Warn("Failed to close connection") } @@ -319,7 +315,7 @@ func (mt *ManagedTransport) setIfConnNil(ctx context.Context, conn *snet.Conn) e mt.conn = conn select { case mt.connCh <- struct{}{}: - mt.log.Infoln("SENT SIGNAL TO CONNCH") + mt.log.Debugln("Sent signal to connCh") default: } return nil @@ -370,7 +366,7 @@ func (mt *ManagedTransport) readPacket() (packet routing.Packet, err error) { var conn *snet.Conn for { if conn = mt.getConn(); conn != nil { - mt.log.Infof("GO CONN IN MANAGED TP: %s", conn.RemoteAddr()) + mt.log.Debugf("Got conn in managed TP: %s", conn.RemoteAddr()) break } select { @@ -381,18 +377,18 @@ func (mt *ManagedTransport) readPacket() (packet routing.Packet, err error) { } h := make(routing.Packet, routing.PacketHeaderSize) - mt.log.Infoln("TRYING TO READ PACKET HEADER...") + mt.log.Debugln("Trying to read packet header...") if _, err = io.ReadFull(conn, h); err != nil { - mt.log.Infof("ERROR READING PACKET HEADER: %v", err) + mt.log.WithError(err).Debugf("Failed to read packet header: %v", err) return nil, err } - mt.log.Infof("READ PACKET HEADER: %s", string(h)) + mt.log.Debugf("Read packet header: %s", string(h)) p := make([]byte, h.Size()) if _, err = io.ReadFull(conn, p); err != nil { - mt.log.Infof("ERROR READING PACKET PAYLOAD: %v", err) + mt.log.WithError(err).Debugf("Error reading packet payload: %v", err) return nil, err } - mt.log.Infoln("READ PACKET PAYLOAD: %s", string(p)) + mt.log.Debugf("Read packet payload: %s", string(p)) packet = append(h, p...) if n := len(packet); n > routing.PacketHeaderSize { mt.logRecv(uint64(n - routing.PacketHeaderSize)) diff --git a/pkg/transport/manager.go b/pkg/transport/manager.go index a7d30abe35..24f9d9fa76 100644 --- a/pkg/transport/manager.go +++ b/pkg/transport/manager.go @@ -106,11 +106,10 @@ func (tm *Manager) serve(ctx context.Context) { return default: if err := tm.acceptTransport(ctx, lis); err != nil { - tm.Logger.Infof("ERROR ACCEPTING TRANSPORT: %v", err) + tm.Logger.Warnf("Failed to accept connection: %s", err) if strings.Contains(err.Error(), "closed") { return } - tm.Logger.Warnf("Failed to accept connection: %s", err) } } } @@ -142,9 +141,9 @@ func (tm *Manager) initTransports(ctx context.Context) { if err != nil { log.Warnf("No transports found for local visor: %v", err) } - tm.Logger.Infof("INITIALIZING %d TRANSPORTS", len(entries)) + tm.Logger.Debugf("Initializing %d transports", len(entries)) for _, entry := range entries { - tm.Logger.Infof("INITIALIZING %v", *entry.Entry) + tm.Logger.Debugf("Initializing TP %v", *entry.Entry) var ( tpType = entry.Entry.Type remote = entry.Entry.RemoteEdge(tm.Conf.PubKey) @@ -153,7 +152,7 @@ func (tm *Manager) initTransports(ctx context.Context) { if _, err := tm.saveTransport(remote, tpType); err != nil { tm.Logger.Warnf("INIT: failed to init tp: type(%s) remote(%s) tpID(%s)", tpType, remote, tpID) } - tm.Logger.Infoln("SUCCESSFULLY INITIALIZED TRANSPORT") + tm.Logger.Debugf("Successfully initialized TP %v", *entry.Entry) } } @@ -177,7 +176,7 @@ func (tm *Manager) acceptTransport(ctx context.Context, lis *snet.Listener) erro mTp, ok := tm.tps[tpID] if !ok { - tm.Logger.Infoln("NO TRANSPORT FOUND, CREATING NEW ONE") + tm.Logger.Debugln("No TP found, creating new one") mTp = NewManagedTransport(tm.n, tm.Conf.DiscoveryClient, tm.Conf.LogStore, conn.RemotePK(), lis.Network()) if err := mTp.Accept(ctx, conn); err != nil { return err @@ -186,7 +185,7 @@ func (tm *Manager) acceptTransport(ctx context.Context, lis *snet.Listener) erro tm.tps[tpID] = mTp } else { - tm.Logger.Infoln("TP FOUND, ACCEPTING") + tm.Logger.Debugln("TP found, accepting...") if err := mTp.Accept(ctx, conn); err != nil { return err } @@ -220,11 +219,11 @@ func (tm *Manager) saveTransport(remote cipher.PubKey, netName string) (*Managed tpID := tm.tpIDFromPK(remote, netName) - tm.Logger.Infof("INITIALIZING TP WITH ID %s", tpID) + tm.Logger.Debugf("Initializing TP with ID %s", tpID) tp, ok := tm.tps[tpID] if ok { - tm.Logger.Infoln("GOT TP FROM MAP") + tm.Logger.Debugln("Got TP from map") return tp, nil }