Refactor debug logs

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 {

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
 	}()
 

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

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
 }

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())

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())
 	}
 

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))

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
 	}