Improved logging.

* Made rpcutil.LogCall to log RPC call on the server side.

* Improved appserver.RPCGateway logging #195

* Changed appcommon.Key to use UUID.

go.mod

@@ -3,7 +3,7 @@ module github.com/SkycoinProject/skywire-mainnet
 go 1.13
 
 require (
-	github.com/SkycoinProject/dmsg v0.0.0-20200304115237-130cc9d98ffb
+	github.com/SkycoinProject/dmsg v0.0.0-20200305081343-7a67392d759d
 	github.com/SkycoinProject/skycoin v0.27.0
 	github.com/SkycoinProject/yamux v0.0.0-20191213015001-a36efeefbf6a
 	github.com/armon/go-socks5 v0.0.0-20160902184237-e75332964ef5

go.sum

@@ -1,8 +1,8 @@
 cloud.google.com/go v0.26.0/go.mod h1:aQUYkXzVsufM+DwF1aE+0xfcU+56JwCaLick0ClmMTw=
 github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03qcyfWMU=
 github.com/OneOfOne/xxhash v1.2.2/go.mod h1:HSdplMjZKSmBqAxg5vPj2TmRDmfkzw+cTzAElWljhcU=
-github.com/SkycoinProject/dmsg v0.0.0-20200304115237-130cc9d98ffb h1:UPgo4kZ/nFV4jI9djG0esOyZjda4IZGZpGl/ntYRyuM=
-github.com/SkycoinProject/dmsg v0.0.0-20200304115237-130cc9d98ffb/go.mod h1:DzykXMLlx6Fx0fGjZsCIRas/MIvxW8DZpmDA6f2nCRk=
+github.com/SkycoinProject/dmsg v0.0.0-20200305081343-7a67392d759d h1:2vjoH2HOsRRvqvXQb2K4uQnqaMRJnYiDpsfCRxixzvs=
+github.com/SkycoinProject/dmsg v0.0.0-20200305081343-7a67392d759d/go.mod h1:DzykXMLlx6Fx0fGjZsCIRas/MIvxW8DZpmDA6f2nCRk=
 github.com/SkycoinProject/skycoin v0.26.0/go.mod h1:xqPLOKh5B6GBZlGA7B5IJfQmCy7mwimD9NlqxR3gMXo=
 github.com/SkycoinProject/skycoin v0.27.0 h1:N3IHxj8ossHOcsxLYOYugT+OaELLncYHJHxbbYLPPmY=
 github.com/SkycoinProject/skycoin v0.27.0/go.mod h1:xqPLOKh5B6GBZlGA7B5IJfQmCy7mwimD9NlqxR3gMXo=

pkg/app/appcommon/key.go

@@ -1,13 +1,14 @@
 package appcommon
 
-import "github.com/SkycoinProject/dmsg/cipher"
+import (
+	"github.com/google/uuid"
+)
 
 // Key is an app key to authenticate within the
 // app server.
 type Key string
 
 // GenerateAppKey generates new app key.
 func GenerateAppKey() Key {
-	raw, _ := cipher.GenerateKeyPair()
-	return Key(raw.Hex())
+	return Key(uuid.New().String())
 }

pkg/app/appserver/rpc_gateway.go

@@ -9,6 +9,8 @@ import (
 
 	"github.com/SkycoinProject/skycoin/src/util/logging"
 
+	"github.com/SkycoinProject/skywire-mainnet/pkg/util/rpcutil"
+
 	"github.com/SkycoinProject/skywire-mainnet/pkg/app/appnet"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/app/idmanager"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/routing"
@@ -77,7 +79,9 @@ type DialResp struct {
 }
 
 // Dial dials to the remote.
-func (r *RPCGateway) Dial(remote *appnet.Addr, resp *DialResp) error {
+func (r *RPCGateway) Dial(remote *appnet.Addr, resp *DialResp) (err error) {
+	defer rpcutil.LogCall(r.log, "Dial", remote)(resp, &err)
+
 	reservedConnID, free, err := r.cm.ReserveNextID()
 	if err != nil {
 		return err
@@ -96,12 +100,10 @@ func (r *RPCGateway) Dial(remote *appnet.Addr, resp *DialResp) error {
 	}
 
 	if err := r.cm.Set(*reservedConnID, wrappedConn); err != nil {
-		if err := wrappedConn.Close(); err != nil {
-			r.log.WithError(err).Error("error closing conn")
+		if cErr := wrappedConn.Close(); cErr != nil {
+			r.log.WithError(cErr).Error("Error closing wrappedConn.")
 		}
-
 		free()
-
 		return err
 	}
 
@@ -114,7 +116,9 @@ func (r *RPCGateway) Dial(remote *appnet.Addr, resp *DialResp) error {
 }
 
 // Listen starts listening.
-func (r *RPCGateway) Listen(local *appnet.Addr, lisID *uint16) error {
+func (r *RPCGateway) Listen(local *appnet.Addr, lisID *uint16) (err error) {
+	defer rpcutil.LogCall(r.log, "Listen", local)(lisID, &err)
+
 	nextLisID, free, err := r.lm.ReserveNextID()
 	if err != nil {
 		return err
@@ -127,17 +131,14 @@ func (r *RPCGateway) Listen(local *appnet.Addr, lisID *uint16) error {
 	}
 
 	if err := r.lm.Set(*nextLisID, l); err != nil {
-		if err := l.Close(); err != nil {
-			r.log.WithError(err).Error("error closing listener")
+		if cErr := l.Close(); cErr != nil {
+			r.log.WithError(cErr).Error("Error closing listener.")
 		}
-
 		free()
-
 		return err
 	}
 
 	*lisID = *nextLisID
-
 	return nil
 }
 
@@ -148,48 +149,42 @@ type AcceptResp struct {
 }
 
 // Accept accepts connection from the listener specified by `lisID`.
-func (r *RPCGateway) Accept(lisID *uint16, resp *AcceptResp) error {
-	r.log.Infoln("Inside RPC Accept on server side")
+func (r *RPCGateway) Accept(lisID *uint16, resp *AcceptResp) (err error) {
+	defer rpcutil.LogCall(r.log, "Accept", lisID)(resp, &err)
+
+	log := r.log.WithField("func", "Accept")
 
+	log.Debug("Getting listener...")
 	lis, err := r.getListener(*lisID)
 	if err != nil {
-		r.log.Infoln("Error getting listener on RPC Accept server side")
 		return err
 	}
 
-	r.log.Infoln("Reserving next ID on RPC Accept server side")
-
+	log.Debug("Reserving next ID...")
 	connID, free, err := r.cm.ReserveNextID()
 	if err != nil {
-		r.log.Infoln("Error reserving next ID on RPC Accept server side")
 		return err
 	}
 
-	r.log.Infoln("Accepting conn on RPC Accept server side")
-
+	log.Debug("Accepting conn...")
 	conn, err := lis.Accept()
 	if err != nil {
-		r.log.Warnf("Error accepting conn on RPC Accept server side: %v", err)
 		free()
-
 		return err
 	}
 
-	r.log.Infoln("Wrapping conn on RPC Accept server side")
-
+	log.Debug("Wrapping conn...")
 	wrappedConn, err := appnet.WrapConn(conn)
 	if err != nil {
 		free()
 		return err
 	}
 
 	if err := r.cm.Set(*connID, wrappedConn); err != nil {
-		if err := wrappedConn.Close(); err != nil {
-			r.log.WithError(err).Error("error closing DMSG transport")
+		if cErr := wrappedConn.Close(); cErr != nil {
+			r.log.WithError(cErr).Error("Failed to close wrappedConn.")
 		}
-
 		free()
-
 		return err
 	}
 
@@ -264,7 +259,9 @@ func (r *RPCGateway) Read(req *ReadReq, resp *ReadResp) error {
 }
 
 // CloseConn closes connection specified by `connID`.
-func (r *RPCGateway) CloseConn(connID *uint16, _ *struct{}) error {
+func (r *RPCGateway) CloseConn(connID *uint16, _ *struct{}) (err error) {
+	defer rpcutil.LogCall(r.log, "CloseConn", connID)(nil, &err)
+
 	conn, err := r.popConn(*connID)
 	if err != nil {
 		return err
@@ -274,7 +271,9 @@ func (r *RPCGateway) CloseConn(connID *uint16, _ *struct{}) error {
 }
 
 // CloseListener closes listener specified by `lisID`.
-func (r *RPCGateway) CloseListener(lisID *uint16, _ *struct{}) error {
+func (r *RPCGateway) CloseListener(lisID *uint16, _ *struct{}) (err error) {
+	defer rpcutil.LogCall(r.log, "CloseConn", lisID)(nil, &err)
+
 	lis, err := r.popListener(*lisID)
 	if err != nil {
 		return err

pkg/app/appserver/server.go

@@ -33,7 +33,7 @@ func New(log *logging.Logger, sockFile string) *Server {
 
 // Register registers an app key in RPC server.
 func (s *Server) Register(appKey appcommon.Key) error {
-	logger := logging.MustGetLogger(fmt.Sprintf("rpc_server_%s", appKey))
+	logger := logging.MustGetLogger(fmt.Sprintf("app_gateway:%s", appKey))
 	gateway := NewRPCGateway(logger)
 
 	return s.rpcS.RegisterName(string(appKey), gateway)

pkg/transport/managed_transport.go

@@ -515,7 +515,7 @@ func (mt *ManagedTransport) WritePacket(ctx context.Context, packet routing.Pack
 
 // WARNING: Not thread safe.
 func (mt *ManagedTransport) readPacket() (packet routing.Packet, err error) {
-	log := mt.log.WithField("func", "readPacket()")
+	log := mt.log.WithField("func", "readPacket")
 
 	var conn *snet.Conn
 	for {

pkg/util/rpcutil/log_call.go

@@ -0,0 +1,36 @@
+package rpcutil
+
+import (
+	"time"
+
+	"github.com/sirupsen/logrus"
+)
+
+// LogCall is used to log an RPC call from the rpc.Server
+func LogCall(log logrus.FieldLogger, method string, in interface{}) func(out interface{}, err *error) {
+
+	// Just in case log is not set.
+	// However, this is dangerous as it may result in a race condition.
+	if log == nil {
+		log = logrus.New()
+	}
+
+	start := time.Now()
+	log = log.
+		WithField("_method", method).
+		WithField("_received", start.Format(time.Kitchen))
+	if in != nil {
+		log = log.WithField("input", in)
+	}
+
+	return func(out interface{}, err *error) {
+		log := log.WithField("_period", time.Since(start).String())
+		if out != nil {
+			log = log.WithField("output", out)
+		}
+		if err != nil && *err != nil {
+			log = log.WithError(*err)
+		}
+		log.Info("Request processed.")
+	}
+}