Merge pull request #325 from filecoin-project/feat/logs-elk

Integrate log collection

chain/store/store.go

@@ -725,7 +725,7 @@ func (cs *ChainStore) GetRandomness(ctx context.Context, blks []cid.Cid, tickets
 	}
 	lt := int64(len(tickets))
 	if lb < lt {
-		log.Desugar().Warn("self sampling randomness. this should be extremely rare, if you see this often it may be a bug", zap.Stack("call-stack"))
+		log.Desugar().Warn("self sampling randomness. this should be extremely rare, if you see this often it may be a bug", zap.Stack("stacktrace"))
 
 		t := tickets[lt-(1+lb)]
 

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,

chain/sync.go

@@ -856,6 +856,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
 }

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
+}

go.mod

@@ -34,7 +34,7 @@ require (
 	github.com/ipfs/go-ipfs-routing v0.1.0
 	github.com/ipfs/go-ipld-cbor v0.0.3
 	github.com/ipfs/go-ipld-format v0.0.2
-	github.com/ipfs/go-log v0.0.2-0.20190905183954-62f287c7db59
+	github.com/ipfs/go-log v0.0.2-0.20190920042044-a609c1ae5144
 	github.com/ipfs/go-merkledag v0.2.3
 	github.com/ipfs/go-unixfs v0.2.2-0.20190827150610-868af2e9e5cb
 	github.com/ipsn/go-secp256k1 v0.0.0-20180726113642-9d62b9f0bc52

go.sum

@@ -254,8 +254,8 @@ github.com/ipfs/go-ipld-format v0.0.1/go.mod h1:kyJtbkDALmFHv3QR6et67i35QzO3S0dC
 github.com/ipfs/go-ipld-format v0.0.2 h1:OVAGlyYT6JPZ0pEfGntFPS40lfrDmaDbQwNHEY2G9Zs=
 github.com/ipfs/go-ipld-format v0.0.2/go.mod h1:4B6+FM2u9OJ9zCV+kSbgFAZlOrv1Hqbf0INGQgiKf9k=
 github.com/ipfs/go-log v0.0.1/go.mod h1:kL1d2/hzSpI0thNYjiKfjanbVNU+IIGA/WnNESY9leM=
-github.com/ipfs/go-log v0.0.2-0.20190905183954-62f287c7db59 h1:gUmFTK1r79usWs8LQJsoMw+yba2qs/EVj9kmPRvSrYM=
+github.com/ipfs/go-log v0.0.2-0.20190920042044-a609c1ae5144 h1:5WM8S1nwquWQ3zEuNhK82NE5Di6Pd41qz9JxxvxTAIA=
-github.com/ipfs/go-log v0.0.2-0.20190905183954-62f287c7db59/go.mod h1:azGN5dH7ailfREknDDNYB0Eq4qZ/4I4Y3gO0ivjJNyM=
+github.com/ipfs/go-log v0.0.2-0.20190920042044-a609c1ae5144/go.mod h1:azGN5dH7ailfREknDDNYB0Eq4qZ/4I4Y3gO0ivjJNyM=
 github.com/ipfs/go-merkledag v0.1.0/go.mod h1:SQiXrtSts3KGNmgOzMICy5c0POOpUNQLvB3ClKnBAlk=
 github.com/ipfs/go-merkledag v0.2.3 h1:aMdkK9G1hEeNvn3VXfiEMLY0iJnbiQQUHnM0HFJREsE=
 github.com/ipfs/go-merkledag v0.2.3/go.mod h1:SQiXrtSts3KGNmgOzMICy5c0POOpUNQLvB3ClKnBAlk=

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
 }

scripts/daemon.service

@@ -4,6 +4,8 @@ After=network.target
 
 [Service]
 ExecStart=/usr/local/bin/lotus daemon
+Environment=GOLOG_FILE="/root/.lotus/logs"
+Environment=GOLOG_LOG_FMT="json"
 
 [Install]
 WantedBy=multiuser.target

scripts/filebeat.yml

@@ -0,0 +1,66 @@
+############################# Filebeat #####################################
+
+filebeat.inputs:
+
+- type: log
+  paths:
+    - /root/.lotusstorage/logs
+  fields:
+    logzio_codec: json
+    token: <API TOKEN>
+    type: lotus-miner
+  fields_under_root: true
+  json.keys_under_root: false
+  encoding: utf-8
+  ignore_older: 3h
+- type: log
+  paths:
+    - /root/.lotus/logs
+  fields:
+    logzio_codec: json
+    token: <API TOKEN>
+    type: lotus-daemon
+  fields_under_root: true
+  json.keys_under_root: false
+  encoding: utf-8
+  ignore_older: 3h
+
+#For version 6.x and lower
+#filebeat.registry_file: /var/lib/filebeat/registry
+
+#For version 7 and higher
+filebeat.registry.path: /var/lib/filebeat
+
+#The following processors are to ensure compatibility with version 7
+processors:
+- rename:
+    fields:
+     - from: "agent"
+       to: "beat_agent"
+    ignore_missing: true
+- rename:
+    fields:
+     - from: "log.file.path"
+       to: "source"
+    ignore_missing: true
+
+- if:
+    has_fields: ['json.ts']
+  then:
+    - timestamp:
+        field: 'json.ts'
+        layouts:
+          - '2006-01-02T15:04:05.000Z0700'
+        test:
+          - '2019-10-10T22:37:48.297+0200'
+    - drop_fields:
+        fields: ['json.ts']
+
+
+############################# Output ##########################################
+
+output:
+  logstash:
+    hosts: ["listener.logz.io:5015"]
+    ssl:
+      certificate_authorities: ['/etc/pki/tls/certs/COMODORSADomainValidationSecureServerCA.crt']

scripts/sminer.service

@@ -4,6 +4,8 @@ After=network.target
 
 [Service]
 ExecStart=/usr/local/bin/lotus-storage-miner run
+Environment=GOLOG_FILE="/root/.lotusstorage/logs"
+Environment=GOLOG_LOG_FMT="json"
 
 [Install]
 WantedBy=multiuser.target

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,