WIP: Improve logging.

skycoin · Jun 1, 2020 · 0c0c05c · 0c0c05c
1 parent 0629799
commit 0c0c05c
Show file tree

Hide file tree

Showing 6 changed files with 34 additions and 36 deletions.
diff --git a/pkg/router/routerclient/client.go b/pkg/router/routerclient/client.go
@@ -12,7 +12,6 @@ import (
 
 	"github.com/SkycoinProject/skywire-mainnet/pkg/routing"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/snet"
-	"github.com/SkycoinProject/skywire-mainnet/pkg/util/rpcutil"
 )
 
 // RPCName is the RPC gateway object name.
@@ -54,23 +53,20 @@ func (c *Client) Close() error {
 // AddEdgeRules adds forward and consume rules to router (forward and reverse).
 func (c *Client) AddEdgeRules(ctx context.Context, rules routing.EdgeRules) (ok bool, err error) {
 	const method = "AddEdgeRules"
-	defer rpcutil.LogCall(c.log, method, rules)(&ok, &err)
 	err = c.call(ctx, method, rules, &ok)
 	return ok, err
 }
 
 // AddIntermediaryRules adds intermediary rules to router.
 func (c *Client) AddIntermediaryRules(ctx context.Context, rules []routing.Rule) (ok bool, err error) {
 	const method = "AddIntermediaryRules"
-	defer rpcutil.LogCall(c.log, method, rules)(&ok, &err)
 	err = c.call(ctx, method, rules, &ok)
 	return ok, err
 }
 
 // ReserveIDs reserves n IDs and returns them.
 func (c *Client) ReserveIDs(ctx context.Context, n uint8) (rtIDs []routing.RouteID, err error) {
 	const method = "ReserveIDs"
-	defer rpcutil.LogCall(c.log, method, n)(&rtIDs, &err)
 	err = c.call(ctx, method, n, &rtIDs)
 	return rtIDs, err
 }

diff --git a/pkg/routing/route.go b/pkg/routing/route.go
@@ -84,8 +84,15 @@ type EdgeRules struct {
 }
 
 // String implements fmt.Stringer
-func (er *EdgeRules) String() string {
-	j, err := json.MarshalIndent(er, "", "\t")
+func (er EdgeRules) String() string {
+	m := map[string]interface{}{
+		"descriptor": er.Desc.String(),
+		"routing_rules": []string{
+			er.Forward.String(),
+			er.Reverse.String(),
+		},
+	}
+	j, err := json.MarshalIndent(m, "", "\t")
 	if err != nil {
 		panic(err)
 	}

diff --git a/pkg/setup/node.go b/pkg/setup/node.go
@@ -10,6 +10,7 @@ import (
 	"github.com/SkycoinProject/dmsg/cipher"
 	"github.com/SkycoinProject/dmsg/disc"
 	"github.com/SkycoinProject/skycoin/src/util/logging"
+	"github.com/sirupsen/logrus"
 
 	"github.com/SkycoinProject/skywire-mainnet/pkg/metrics"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/router/routerclient"
@@ -107,9 +108,12 @@ func (sn *Node) Serve(ctx context.Context) error {
 // * Edge rules are broadcasted to the responding router.
 // * Edge rules is returned (to the initiating router).
 func CreateRouteGroup(ctx context.Context, dialer snet.Dialer, biRt routing.BidirectionalRoute) (resp routing.EdgeRules, err error) {
-	log := log.WithField("func", fmt.Sprintf("REQ[%s->%s]", biRt.Desc.SrcPK(), biRt.Desc.DstPK()))
+	start := time.Now()
+	log := logging.MustGetLogger(fmt.Sprintf("request:%s->%s", biRt.Desc.SrcPK(), biRt.Desc.DstPK()))
 	log.Info("Processing request.")
 	defer func() {
+		elapsed := time.Since(start)
+		log := log.WithField("elapsed", elapsed)
 		if err != nil {
 			log.WithError(err).Warn("Request processed with error.")
 		} else {
@@ -123,7 +127,7 @@ func CreateRouteGroup(ctx context.Context, dialer snet.Dialer, biRt routing.Bidi
 	}
 
 	// Reserve route IDs from remote routers.
-	rtIDR, err := ReserveRouteIDs(ctx, dialer, biRt)
+	rtIDR, err := ReserveRouteIDs(ctx, log, dialer, biRt)
 	if err != nil {
 		return routing.EdgeRules{}, err
 	}
@@ -138,22 +142,21 @@ func CreateRouteGroup(ctx context.Context, dialer snet.Dialer, biRt routing.Bidi
 	// Rules are grouped by rule type [FWD, REV, INTER].
 	fwdRules, revRules, interRules, err := GenerateRules(rtIDR, []routing.Route{fwdRt, revRt})
 	if err != nil {
-		log.WithError(err).Error("Generating routing rules returned non-nil error.")
 		return routing.EdgeRules{}, err
 	}
 	initEdge := routing.EdgeRules{Desc: revRt.Desc, Forward: fwdRules[srcPK][0], Reverse: revRules[srcPK][0]}
 	respEdge := routing.EdgeRules{Desc: fwdRt.Desc, Forward: fwdRules[dstPK][0], Reverse: revRules[dstPK][0]}
 
-	log.WithField("rules", initEdge).Info("Rules for INITIATING router.")
-	log.WithField("rules", respEdge).Info("Rules for RESPONDING router.")
-	log.WithField("rules", interRules).Info("Rules for INTERMEDIARY routers.")
+	log.Infof("Generated routing rules:\nInitiating edge: %v\nResponding edge: %v\nIntermediaries: %v",
+		initEdge.String(), respEdge.String(), interRules.String())
 
 	// Broadcast intermediary rules to intermediary routers.
-	if err := BroadcastIntermediaryRules(ctx, rtIDR, interRules); err != nil {
+	if err := BroadcastIntermediaryRules(ctx, log, rtIDR, interRules); err != nil {
 		return routing.EdgeRules{}, err
 	}
 
 	// Broadcast rules to responding router.
+	log.Debug("Broadcasting responding rules...")
 	ok, err := rtIDR.Client(biRt.Desc.DstPK()).AddEdgeRules(ctx, respEdge)
 	if err != nil || !ok {
 		return routing.EdgeRules{}, fmt.Errorf("failed to broadcast rules to destination router: %v", err)
@@ -165,14 +168,11 @@ func CreateRouteGroup(ctx context.Context, dialer snet.Dialer, biRt routing.Bidi
 
 // ReserveRouteIDs dials to all routers and reserves required route IDs from them.
 // The number of route IDs to be reserved per router, is extrapolated from the 'route' input.
-func ReserveRouteIDs(ctx context.Context, dialer snet.Dialer, route routing.BidirectionalRoute) (idR IDReserver, err error) {
-	log := log.WithField("func", "ReserveRouteIDs")
-	log.Info("Starting.")
+func ReserveRouteIDs(ctx context.Context, log logrus.FieldLogger, dialer snet.Dialer, route routing.BidirectionalRoute) (idR IDReserver, err error) {
+	log.Debug("Reserving route IDs...")
 	defer func() {
 		if err != nil {
-			log.WithError(err).Warn("Failed.")
-		} else {
-			log.Info("Success.")
+			log.WithError(err).Warn("Failed to reserve route IDs.")
 		}
 	}()
 
@@ -242,14 +242,11 @@ func GenerateRules(idR IDReserver, routes []routing.Route) (fwdRules, revRules,
 }
 
 // BroadcastIntermediaryRules broadcasts routing rules to the intermediary routers.
-func BroadcastIntermediaryRules(ctx context.Context, rtIDR IDReserver, interRules RulesMap) (err error) {
-	log := log.WithField("func", "BroadcastIntermediaryRules")
-	log.WithField("intermediary_routers", len(interRules)).Info("Starting.")
+func BroadcastIntermediaryRules(ctx context.Context, log logrus.FieldLogger, rtIDR IDReserver, interRules RulesMap) (err error) {
+	log.WithField("intermediary_routers", len(interRules)).Debug("Broadcasting intermediary rules...")
 	defer func() {
 		if err != nil {
-			log.WithError(err).Warn("Failed.")
-		} else {
-			log.Info("Success.")
+			log.WithError(err).Warn("Failed to broadcast intermediary rules.")
 		}
 	}()
 

diff --git a/pkg/setup/node_test.go b/pkg/setup/node_test.go
@@ -10,6 +10,7 @@ import (
 
 	"github.com/SkycoinProject/dmsg/cipher"
 	"github.com/google/uuid"
+	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 
@@ -106,7 +107,7 @@ func TestBroadcastIntermediaryRules(t *testing.T) {
 			defer cancel()
 
 			// act
-			err := BroadcastIntermediaryRules(ctx, rtIDR, rules)
+			err := BroadcastIntermediaryRules(ctx, logrus.New(), rtIDR, rules)
 
 			// assert
 			if tc.failingRouters > 0 {

diff --git a/pkg/setup/rpc_gateway.go b/pkg/setup/rpc_gateway.go
@@ -11,7 +11,6 @@ import (
 	"github.com/SkycoinProject/skywire-mainnet/pkg/metrics"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/routing"
 	"github.com/SkycoinProject/skywire-mainnet/pkg/snet"
-	"github.com/SkycoinProject/skywire-mainnet/pkg/util/rpcutil"
 )
 
 // RPCGateway is a RPC interface for setup node.
@@ -27,17 +26,10 @@ type RPCGateway struct {
 
 // DialRouteGroup dials RouteGroups for route and rules.
 func (g *RPCGateway) DialRouteGroup(route routing.BidirectionalRoute, rules *routing.EdgeRules) (err error) {
-	const method = "DialRouteGroup"
-
-	log := logging.MustGetLogger("req:" + g.ReqPK.String())
-	log.WithField("_method", method).Info("Request received.")
+	log := logging.MustGetLogger("request:" + g.ReqPK.String())
 
 	startTime := time.Now()
-	logCall := rpcutil.LogCall(log, method, route)
-	defer func() {
-		g.Metrics.Record(time.Since(startTime), err != nil)
-		logCall(rules, &err)
-	}()
+	defer func() { g.Metrics.Record(time.Since(startTime), err != nil) }()
 
 	ctx, cancel := context.WithTimeout(g.Ctx, g.Timeout)
 	defer cancel()

diff --git a/pkg/visor/visorconfig/types.go b/pkg/visor/visorconfig/types.go
@@ -27,6 +27,11 @@ func (d Duration) MarshalJSON() ([]byte, error) {
 
 // UnmarshalJSON implements unmarshal from json
 func (d *Duration) UnmarshalJSON(b []byte) error {
+	if len(b) == 0 {
+		*d = 0
+		return nil
+	}
+
 	var v interface{}
 	if err := json.Unmarshal(b, &v); err != nil {
 		return err