From 49e3fe39f8c0a8424ba308ac3eda5d6d3cf23a02 Mon Sep 17 00:00:00 2001
From: Jakub Sztandera <kubuxu@protocol.ai>
Date: Fri, 11 Oct 2019 01:41:48 +0200
Subject: [PATCH] Structure logs

License: MIT
Signed-off-by: Jakub Sztandera <kubuxu@protocol.ai>
---
 chain/sub/incoming.go |  2 +-
 chain/sync.go         |  1 +
 chain/types/logs.go   | 17 +++++++++++++++++
 miner/miner.go        |  4 ++--
 storage/post.go       | 20 +++++++++++++-------
 5 files changed, 34 insertions(+), 10 deletions(-)
 create mode 100644 chain/types/logs.go

diff --git a/chain/sub/incoming.go b/chain/sub/incoming.go
index b7fd6d700..ab03c999f 100644
--- a/chain/sub/incoming.go
+++ b/chain/sub/incoming.go
@@ -44,7 +44,7 @@ func HandleIncomingBlocks(ctx context.Context, bsub *pubsub.Subscription, s *cha
 				return
 			}
 
-			log.Infof("inform new block over pubsub: %s from %s", blk.Header.Cid(), msg.GetFrom())
+			log.Infow("new block over pubsub", "cid", blk.Header.Cid(), "source", msg.GetFrom())
 			s.InformNewBlock(msg.GetFrom(), &types.FullBlock{
 				Header:        blk.Header,
 				BlsMessages:   bmsgs,
diff --git a/chain/sync.go b/chain/sync.go
index db7da3e6b..b53892602 100644
--- a/chain/sync.go
+++ b/chain/sync.go
@@ -852,6 +852,7 @@ func (syncer *Syncer) collectChain(ctx context.Context, ts *types.TipSet) error
 	}
 
 	syncer.syncState.SetStage(api.StageSyncComplete)
+	log.Infow("new tipset", "height", ts.Height(), "tipset", types.LogCids(ts.Cids()))
 
 	return nil
 }
diff --git a/chain/types/logs.go b/chain/types/logs.go
new file mode 100644
index 000000000..e9a69e9d5
--- /dev/null
+++ b/chain/types/logs.go
@@ -0,0 +1,17 @@
+package types
+
+import (
+	"github.com/ipfs/go-cid"
+	"go.uber.org/zap/zapcore"
+)
+
+type LogCids []cid.Cid
+
+var _ zapcore.ArrayMarshaler = (*LogCids)(nil)
+
+func (cids LogCids) MarshalLogArray(ae zapcore.ArrayEncoder) error {
+	for _, c := range cids {
+		ae.AppendString(c.String())
+	}
+	return nil
+}
diff --git a/miner/miner.go b/miner/miner.go
index 1a7a6c3c7..9ef74787d 100644
--- a/miner/miner.go
+++ b/miner/miner.go
@@ -219,7 +219,7 @@ func (m *Miner) GetBestMiningCandidate() (*MiningBase, error) {
 }
 
 func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg, error) {
-	log.Info("attempting to mine a block on:", base.ts.Cids())
+	log.Infow("attempting to mine a block", "tipset", types.LogCids(base.ts.Cids()))
 	ticket, err := m.scratchTicket(ctx, base)
 	if err != nil {
 		return nil, errors.Wrap(err, "scratching ticket failed")
@@ -239,7 +239,7 @@ func (m *Miner) mineOne(ctx context.Context, base *MiningBase) (*types.BlockMsg,
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to create block")
 	}
-	log.Infof("mined new block: %s", b.Cid())
+	log.Infow("mined new block", "cid", b.Cid())
 
 	return b, nil
 }
diff --git a/storage/post.go b/storage/post.go
index 8f4e9686c..0b49ff509 100644
--- a/storage/post.go
+++ b/storage/post.go
@@ -2,7 +2,7 @@ package storage
 
 import (
 	"context"
-	"encoding/base64"
+	"time"
 
 	"golang.org/x/xerrors"
 
@@ -67,14 +67,14 @@ func (m *Miner) scheduleNextPost(ppe uint64) {
 
 	headPPE, provingPeriod := actors.ProvingPeriodEnd(ppe, ts.Height())
 	if headPPE > ppe {
-		log.Warn("PoSt computation running behind chain")
+		log.Warnw("PoSt computation running behind chain", "headPPE", headPPE, "ppe", ppe)
 		ppe = headPPE
 	}
 
 	m.schedLk.Lock()
 	if m.schedPost >= ppe {
 		// this probably can't happen
-		log.Error("PoSt already scheduled: %d >= %d", m.schedPost, ppe)
+		log.Errorw("PoSt already scheduled", "schedPost", m.schedPost, "ppe", ppe)
 		m.schedLk.Unlock()
 		return
 	}
@@ -82,7 +82,8 @@ func (m *Miner) scheduleNextPost(ppe uint64) {
 	m.schedPost = ppe
 	m.schedLk.Unlock()
 
-	log.Infof("Scheduling post at height %d (head=%d; ppe=%d, period=%d)", ppe-build.PoSTChallangeTime, ts.Height(), ppe, provingPeriod)
+	log.Infow("scheduling PoSt", "post-height", ppe-build.PoSTChallangeTime,
+		"height", ts.Height(), "ppe", ppe, "proving-period", provingPeriod)
 	err = m.events.ChainAt(m.computePost(ppe), func(ts *types.TipSet) error { // Revert
 		// TODO: Cancel post
 		log.Errorf("TODO: Cancel PoSt, re-run")
@@ -90,7 +91,7 @@ func (m *Miner) scheduleNextPost(ppe uint64) {
 	}, PoStConfidence, ppe-build.PoSTChallangeTime)
 	if err != nil {
 		// TODO: This is BAD, figure something out
-		log.Errorf("scheduling PoSt failed: %s", err)
+		log.Errorf("scheduling PoSt failed: %+v", err)
 		return
 	}
 }
@@ -110,14 +111,19 @@ func (m *Miner) computePost(ppe uint64) func(ts *types.TipSet, curH uint64) erro
 			return xerrors.Errorf("failed to get chain randomness for post (ts=%d; ppe=%d): %w", ts.Height(), ppe, err)
 		}
 
-		log.Infof("running PoSt computation, rh=%d r=%s, ppe=%d, h=%d", int64(ts.Height())-int64(ppe)+int64(build.PoSTChallangeTime), base64.StdEncoding.EncodeToString(r), ppe, ts.Height())
+		log.Infow("running PoSt", "delayed-by",
+			int64(ts.Height())-(int64(ppe)-int64(build.PoSTChallangeTime)),
+			"chain-random", r, "ppe", ppe, "height", ts.Height())
+
+		tsStart := time.Now()
 		var faults []uint64
 		proof, err := m.secst.RunPoSt(ctx, sset, r, faults)
 		if err != nil {
 			return xerrors.Errorf("running post failed: %w", err)
 		}
+		elapsed := time.Since(tsStart)
 
-		log.Infof("submitting PoSt pLen=%d", len(proof))
+		log.Infow("submitting PoSt", "pLen", len(proof), "elapsed", elapsed)
 
 		params := &actors.SubmitPoStParams{
 			Proof:   proof,