Further improvements with logging.

pkg/app/appnet/skywire_networker.go

@@ -5,6 +5,7 @@ import (
 	"errors"
 	"io"
 	"net"
+	"strings"
 	"sync"
 	"sync/atomic"
 
@@ -87,8 +88,8 @@ func (r *SkywireNetworker) ListenContext(ctx context.Context, addr Addr) (net.Li
 
 	if atomic.CompareAndSwapInt32(&r.isServing, 0, 1) {
 		go func() {
-			if err := r.serveLoop(ctx); err != nil {
-				r.log.WithError(err).Error("error serving")
+			if err := r.serveLoop(ctx); err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
+				r.log.WithError(err).Error("serveLoop stopped unexpectedly.")
 			}
 		}()
 	}
@@ -98,16 +99,21 @@ func (r *SkywireNetworker) ListenContext(ctx context.Context, addr Addr) (net.Li
 
 // serveLoop accepts and serves routes.
 func (r *SkywireNetworker) serveLoop(ctx context.Context) error {
+	log := r.log.WithField("func", "serveLoop")
+
 	for {
-		r.log.Infoln("Trying to accept routing group...")
+		log.Debug("Awaiting to accept route group...")
 
 		rg, err := r.r.AcceptRoutes(ctx)
 		if err != nil {
-			r.log.Infof("Error accepting routing group: %v", err)
+			log.WithError(err).Info("Stopped accepting routes.")
 			return err
 		}
 
-		r.log.Infoln("Accepted routing group")
+		log.
+			WithField("local", rg.LocalAddr()).
+			WithField("remote", rg.RemoteAddr()).
+			Info("Accepted route group.")
 
 		go r.serve(rg)
 	}

pkg/app/appserver/proc_manager.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"io"
 	"os/exec"
+	"strings"
 	"sync"
 
 	"github.com/SkycoinProject/skycoin/src/util/logging"
@@ -140,11 +141,12 @@ func (m *procManager) StopAll() {
 	defer m.mx.Unlock()
 
 	for name, proc := range m.procs {
-		if err := proc.Stop(); err != nil {
-			m.log.WithError(err).Errorf("(%s) failed to stop app", name)
-		} else {
-			m.log.Infof("(%s) app stopped successfully", name)
+		log := m.log.WithField("app_name", name)
+		if err := proc.Stop(); err != nil && strings.Contains(err.Error(), "process already finished") {
+			log.WithError(err).Error("Failed to stop app.")
+			continue
 		}
+		log.Infof("App stopped successfully.")
 	}
 
 	m.procs = make(map[string]*Proc)

pkg/app/appserver/server.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"net"
 	"net/rpc"
+	"strings"
 	"sync"
 
 	"github.com/SkycoinProject/skycoin/src/util/logging"
@@ -81,8 +82,8 @@ func (s *Server) serveConn(conn net.Conn) {
 
 	<-s.stopCh
 
-	if err := conn.Close(); err != nil {
-		s.log.WithError(err).Error("error closing conn")
+	if err := conn.Close(); err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
+		s.log.WithError(err).Error("Unexpected error while closing conn.")
 	}
 
 	s.done.Done()

pkg/app/client.go

@@ -6,6 +6,7 @@ import (
 	"net"
 	"net/rpc"
 	"os"
+	"strings"
 
 	"github.com/SkycoinProject/dmsg/cipher"
 	"github.com/SkycoinProject/skycoin/src/util/logging"
@@ -115,8 +116,8 @@ func (c *Client) Dial(remote appnet.Addr) (net.Conn, error) {
 	if err != nil {
 		conn.freeConnMx.Unlock()
 
-		if err := conn.Close(); err != nil {
-			c.log.WithError(err).Error("error closing conn")
+		if err := conn.Close(); err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
+			c.log.WithError(err).Error("Unexpected error while closing conn.")
 		}
 
 		return nil, err
@@ -201,13 +202,13 @@ func (c *Client) Close() {
 
 	for _, lis := range listeners {
 		if err := lis.Close(); err != nil {
-			c.log.WithError(err).Error("error closing listener")
+			c.log.WithError(err).Error("Error closing listener.")
 		}
 	}
 
 	for _, conn := range conns {
-		if err := conn.Close(); err != nil {
-			c.log.WithError(err).Error("error closing conn")
+		if err := conn.Close(); err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
+			c.log.WithError(err).Error("Unexpected error while closing conn.")
 		}
 	}
 }

pkg/router/router.go

@@ -11,6 +11,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/SkycoinProject/dmsg"
 	"github.com/SkycoinProject/dmsg/cipher"
 	"github.com/SkycoinProject/skycoin/src/util/logging"
 
@@ -286,7 +287,11 @@ func (r *router) serveTransportManager(ctx context.Context) {
 	for {
 		packet, err := r.tm.ReadPacket()
 		if err != nil {
-			r.logger.WithError(err).Errorf("Failed to read packet")
+			if err == transport.ErrNotServing {
+				r.logger.WithError(err).Info("Stopped reading packets")
+				return
+			}
+			r.logger.WithError(err).Error("Stopped reading packets due to unexpected error.")
 			return
 		}
 
@@ -305,7 +310,12 @@ func (r *router) serveSetup() {
 	for {
 		conn, err := r.sl.AcceptConn()
 		if err != nil {
-			r.logger.WithError(err).Warnf("setup client stopped serving")
+			log := r.logger.WithError(err)
+			if err == dmsg.ErrEntityClosed {
+				log.Info("Setup client stopped serving.")
+			} else {
+				log.Error("Setup client stopped serving due to unexpected error.")
+			}
 			return
 		}
 

pkg/transport/managed_transport.go

@@ -543,7 +543,7 @@ func (mt *ManagedTransport) readPacket() (packet routing.Packet, err error) {
 		log.WithError(err).Debugf("Failed to read packet payload.")
 		return nil, err
 	}
-	log.WithField("payload_len", len(p)).WithField("payload_raw", p).Debug("Read packet payload.")
+	log.WithField("payload_len", len(p)).Debug("Read packet payload.")
 
 	packet = append(h, p...)
 	if n := len(packet); n > routing.PacketHeaderSize {

pkg/visor/visor.go

@@ -223,8 +223,8 @@ func NewVisor(cfg *Config, logger *logging.MasterLogger, restartCtx *restart.Con
 	visor.appRPCServer = appserver.New(logging.MustGetLogger("app_rpc_server"), visor.conf.AppServerSockFile)
 
 	go func() {
-		if err := visor.appRPCServer.ListenAndServe(); err != nil {
-			visor.logger.WithError(err).Error("error serving RPC")
+		if err := visor.appRPCServer.ListenAndServe(); err != nil && !strings.Contains(err.Error(), "use of closed network connection") {
+			visor.logger.WithError(err).Error("Serve app_rpc stopped.")
 		}
 	}()
 
@@ -279,7 +279,10 @@ func (visor *Visor) startApps() {
 
 		go func(a AppConfig) {
 			if err := visor.SpawnApp(&a, nil); err != nil {
-				visor.logger.Warnf("App %s stopped working: %v", a.App, err)
+				visor.logger.
+					WithError(err).
+					WithField("app_name", a.App).
+					Warn("App stopped.")
 			}
 		}(ac)
 	}
@@ -456,19 +459,21 @@ func (visor *Visor) Close() (err error) {
 	visor.procManager.StopAll()
 
 	if err = visor.router.Close(); err != nil {
-		visor.logger.WithError(err).Error("failed to stop router")
+		visor.logger.WithError(err).Error("Failed to stop router.")
 	} else {
-		visor.logger.Info("router stopped successfully")
+		visor.logger.Info("Router stopped successfully.")
 	}
 
 	if err := visor.appRPCServer.Close(); err != nil {
-		visor.logger.WithError(err).Error("error closing RPC server")
+		visor.logger.WithError(err).Error("RPC server closed with error.")
 	}
 
 	if err := UnlinkSocketFiles(visor.conf.AppServerSockFile); err != nil {
-		visor.logger.WithError(err).Errorf("Failed to unlink socket file %s", visor.conf.AppServerSockFile)
+		visor.logger.WithError(err).WithField("file_name", visor.conf.AppServerSockFile).
+			Error("Failed to unlink socket file.")
 	} else {
-		visor.logger.Infof("Socket file %s removed successfully", visor.conf.AppServerSockFile)
+		visor.logger.WithField("file_name", visor.conf.AppServerSockFile).
+			Debug("Socket file removed successfully.")
 	}
 
 	return err
@@ -513,7 +518,10 @@ func (visor *Visor) StartApp(appName string) error {
 
 			go func(app AppConfig) {
 				if err := visor.SpawnApp(&app, startCh); err != nil {
-					visor.logger.Warnf("App %s stopped working: %v", appName, err)
+					visor.logger.
+						WithError(err).
+						WithField("app_name", appName).
+						Warn("App stopped.")
 				}
 			}(app)
 
@@ -527,7 +535,10 @@ func (visor *Visor) StartApp(appName string) error {
 
 // SpawnApp configures and starts new App.
 func (visor *Visor) SpawnApp(config *AppConfig, startCh chan<- struct{}) (err error) {
-	visor.logger.Infof("Starting %s", config.App)
+	visor.logger.
+		WithField("app_name", config.App).
+		WithField("args", config.Args).
+		Info("Spawning app.")
 
 	if app, ok := reservedPorts[config.Port]; ok && app != config.App {
 		return fmt.Errorf("can't bind to reserved port %d", config.Port)