diff --git a/chain/store/store.go b/chain/store/store.go index 5e9e17f03..ba710ee63 100644 --- a/chain/store/store.go +++ b/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)] 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 3611f8d61..b03ec5e10 100644 --- a/chain/sync.go +++ b/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 } 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/go.mod b/go.mod index 807508321..8ab84c6fd 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index abbe9d439..4d000e1a4 100644 --- a/go.sum +++ b/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.20190905183954-62f287c7db59/go.mod h1:azGN5dH7ailfREknDDNYB0Eq4qZ/4I4Y3gO0ivjJNyM= +github.com/ipfs/go-log v0.0.2-0.20190920042044-a609c1ae5144 h1:5WM8S1nwquWQ3zEuNhK82NE5Di6Pd41qz9JxxvxTAIA= +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= 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/scripts/daemon.service b/scripts/daemon.service index 2055e4371..8d93518b5 100644 --- a/scripts/daemon.service +++ b/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 \ No newline at end of file +WantedBy=multiuser.target diff --git a/scripts/filebeat.yml b/scripts/filebeat.yml new file mode 100644 index 000000000..0a027b655 --- /dev/null +++ b/scripts/filebeat.yml @@ -0,0 +1,66 @@ +############################# Filebeat ##################################### + +filebeat.inputs: + +- type: log + paths: + - /root/.lotusstorage/logs + fields: + logzio_codec: json + 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: + 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'] diff --git a/scripts/sminer.service b/scripts/sminer.service index c5453ef06..ed966a5d2 100644 --- a/scripts/sminer.service +++ b/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 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,