log_display_green.go

// ---
//2017-12-19 08:55:03 Discover ➫⟪#      0 0xd4e5674…⟫ ~⟪   0 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 1/25 peers⟫  qos=⟪rtt=18s ttl=1m0s conf=1.00⟫
//2017-12-19 08:55:17 ◼⋯⋯⬇ Start ⟪Peer id=931f21921fcc7654 eth/63 [Parity/v1.8.3-beta-b49c44a-20171114/x86_64-linux-gnu/rustc1.21.0] [hs 0.00/s, bs 0.00/s, rs 0.00/s, ss 0.00/s, miss    0, rtt 20s]⟫ hash=⟪0xc5ea430…⟫ TD=⟪185549045030301150788⟫
//2017-12-19 08:55:19 ◼⋯⋯❐ Insert headers=⟪processed=   0 ignored= 192⟫ ❐=⟪n=1836399 hash=0x1ecf991…⟫took=⟪73.546ms⟫
//2017-12-19 08:55:20 ◼⋯⋯❐ Insert headers=⟪processed=   0 ignored= 192⟫ ❐=⟪n=1836591 hash=0xcff7c3c…⟫took=⟪275.686ms⟫
//2017-12-19 08:57:25 ◼⋯⋯⬇ Fail  ⟪Peer id=931f21921fcc7654 eth/63 [Parity/v1.8.3-beta-b49c44a-20171114/x86_64-linux-gnu/rustc1.21.0] [hs 211.71/s, bs 124.20/s, rs 184.06/s, ss 735.50/s, miss    0, rtt 1.512187158s]⟫ err=⟪content processing canceled (requested)⟫
//2017-12-19 09:00:43 ◼⋯⋯⬇ Start ⟪Peer id=f30acc4f9c1a4369 eth/63 [Parity/v1.8.4-beta-c74c8c1-20171211/x86_64-linux-gnu/rustc1.22.1] [hs 0.00/s, bs 0.00/s, rs 0.00/s, ss 0.00/s, miss    0, rtt 20s]⟫ hash=⟪0x26f9a91…⟫ TD=⟪185552382866154347587⟫
//2017-12-19 09:00:46 Sync ︎◉⟪#5043160 0xed71bef…⟫ ~⟪   0 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 5/25 peers⟫ height=⟪5047421 99.92%⟫ qos=⟪rtt=15.942s ttl=1m0s conf=0.70⟫
//2017-12-19 09:00:51 ◼⋯⋯◼ Insert blocks=⟪processed=  48 queued=   0 ignored=   0 txs= 341⟫ ◼=⟪n= 5043208 hash=0x195123c… time=16h55m40.639s ago⟫ took=⟪5.692s⟫
//2017-12-19 09:01:47 Sync ︎◉⟪#5044175 0xedb389d…⟫ ~⟪  16 blks  142 txs  3 mgas  /sec⟫ ✌︎︎︎⟪ 8/25 peers⟫ height=⟪5047421 99.94%⟫ qos=⟪rtt=9.585s ttl=36.603s conf=0.87⟫
//2017-12-19 09:02:43 ◼⋯⋯◼ Insert blocks=⟪processed=2048 queued=   0 ignored=   0 txs=17899⟫ ◼=⟪n= 5045256 hash=0xcf3d3fb… time=8h49m5.014s ago⟫ took=⟪1m51.251s⟫
//2017-12-19 09:03:47 Sync ︎◉⟪#5046394 0x8b10bdd…⟫ ~⟪  36 blks  306 txs  9 mgas  /sec⟫ ✌︎︎︎⟪11/25 peers⟫ height=⟪5047421 99.98%⟫ qos=⟪rtt=6.695s ttl=22.328s conf=1.00⟫
//2017-12-19 09:04:43 ◼⋯⋯◼ Insert blocks=⟪processed=2048 queued=   0 ignored=   0 txs=18124⟫ ◼=⟪n= 5047304 hash=0xc0b4780… time=33m45.455s ago⟫ took=⟪2m0.462s⟫
//2017-12-19 09:04:50 ◼⋯⋯⬇ Done  ⟪Peer id=f30acc4f9c1a4369 eth/63 [Parity/v1.8.4-beta-c74c8c1-20171211/x86_64-linux-gnu/rustc1.22.1] [hs 813.97/s, bs 295.27/s, rs 0.00/s, ss 0.00/s, miss    0, rtt 1.918361657s]⟫ hash=⟪0x26f9a91…⟫ TD=⟪185552382866154347587⟫
//2017-12-19 09:04:50 ◼⋯⋯◼ Insert blocks=⟪processed= 118 queued=   0 ignored=   0 txs=1183⟫ ◼=⟪n= 5047422 hash=0xc47a4fc… time=4m24.711s ago⟫ took=⟪7.258s⟫
//2017-12-19 09:04:51 ◼⋯⋯⬇ Start ⟪Peer id=f30acc4f9c1a4369 eth/63 [Parity/v1.8.4-beta-c74c8c1-20171211/x86_64-linux-gnu/rustc1.22.1] [hs 0.00/s, bs 0.00/s, rs 0.00/s, ss 0.00/s, miss    0, rtt 1.918361657s]⟫ hash=⟪0x249c344…⟫ TD=⟪185554240788446349916⟫
//2017-12-19 09:04:52 ◼⋯⋯◼ Insert blocks=⟪processed=   4 queued=   0 ignored=   0 txs=  53⟫ ◼=⟪n= 5047426 hash=0x6aff1b9… time=3m21.897s ago⟫ took=⟪185ms⟫
//2017-12-19 09:04:53 ◼⋯⋯⬇ Done  ⟪Peer id=f30acc4f9c1a4369 eth/63 [Parity/v1.8.4-beta-c74c8c1-20171211/x86_64-linux-gnu/rustc1.22.1] [hs 0.00/s, bs 1.18/s, rs 0.00/s, ss 0.00/s, miss    0, rtt 1.743539409s]⟫ hash=⟪0x249c344…⟫ TD=⟪185554240788446349916⟫
//2017-12-19 09:04:53 ◼⋯⋯◼ Insert blocks=⟪processed=  11 queued=   0 ignored=   0 txs= 119⟫ ◼=⟪n= 5047437 hash=0x3950d3d… time=1m27.504s ago⟫ took=⟪735ms⟫
//2017-12-19 09:09:53 ◼⋯⋯◼ Insert blocks=⟪processed=  13 queued=   0 ignored=   0 txs= 124⟫ ◼=⟪n= 5047453 hash=0xff69a28… time=19.599s ago⟫ took=⟪630ms⟫
//2017-12-19 09:10:11 ◼⋯⋯◼ Insert blocks=⟪processed=   1 queued=   0 ignored=   0 txs=   1⟫ ◼=⟪n= 5047454 hash=0xd03268a… time=34.122s ago⟫ took=⟪8ms⟫
//2017-12-19 09:10:18 ◼⋯⋯◼ Insert blocks=⟪processed=   1 queued=   0 ignored=   0 txs=   7⟫ ◼=⟪n= 5047455 hash=0x1364b57… time=13.649s ago⟫ took=⟪17ms⟫
//2017-12-19 09:10:25 ◼⋯⋯◼ Insert blocks=⟪processed=   1 queued=   0 ignored=   0 txs=   6⟫ ◼=⟪n= 5047456 hash=0x00ee977… time=12.328s ago⟫ took=⟪23ms⟫
// ---

package main

import (
	"time"
	"fmt"
	"math/big"
	"github.com/ellaism/go-ellaism/logger"
	"strings"
	"github.com/ellaism/go-ellaism/logger/glog"
	"github.com/ellaism/go-ellaism/eth"
	"github.com/ellaism/go-ellaism/eth/downloader"
	"gopkg.in/urfave/cli.v1"
	"github.com/ellaism/go-ellaism/core"
)

var lsModeIcon = []string{
	"",
	"︎◉",
	"◎",
	"▶︎",
}

var dominoes = []string{"🁣", "🁤", "🁥", "🁦", "🁭", "🁴", "🁻", "🁼", "🂃", "🂄", "🂋", "🂌", "🂓"} // 🁣🁤🁥🁦🁭🁴🁻🁼🂃🂄🂋🂌🂓
var chainIcon = "◼⋯⋯" + logger.ColorGreen("◼")
var forkIcon = "◼⋯⦦" + logger.ColorGreen("◼")
var headerIcon = "◼⋯⋯" + logger.ColorGreen("❐")
var downloaderIcon = "◼⋯⋯" + logger.ColorGreen("⬇")
var minedIcon = "◼⋯⋯" + logger.ColorGreen("⟠")
var lsModeDiscoverSpinners = []string{"➫", "➬", "➭"}

func greenParenify(s string) string {
	return logger.ColorGreen("⟪") + s + logger.ColorGreen("⟫")
}
func redParenify(s string) string {
	return logger.ColorRed("⟪") + s + logger.ColorRed("⟫")
}

// greenDisplaySystem is "spec'd" in PR #423 and is a little fancier/more detailed and colorful than basic.
var greenDisplaySystem = displayEventHandlers{
	{
		eventT: logEventChainInsert,
		ev:     core.ChainInsertEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case core.ChainInsertEvent:
					glog.D(logger.Info).Infof(chainIcon+" Insert "+logger.ColorGreen("blocks")+"=%s "+logger.ColorGreen("◼")+"=%s "+logger.ColorGreen("took")+"=%s",
						greenParenify(fmt.Sprintf("processed=%4d queued=%4d ignored=%4d txs=%4d", d.Processed, d.Queued, d.Ignored, d.TxCount)),
						greenParenify(fmt.Sprintf("n=%8d hash=%s… time=%v ago", d.LastNumber, d.LastHash.Hex()[:9], time.Since(d.LatestBlockTime).Round(time.Millisecond))),
						greenParenify(fmt.Sprintf("%v", d.Elasped.Round(time.Millisecond))),
					)
					if bool(glog.D(logger.Info)) {
						chainEventLastSent = time.Now()
					}
				}
			},
		},
	},
	{
		eventT: logEventChainInsertSide,
		ev:     core.ChainSideEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case core.ChainSideEvent:
					glog.D(logger.Info).Infof(forkIcon+" Insert "+logger.ColorGreen("forked block")+"=%s", greenParenify(fmt.Sprintf("n=%8d hash=%s…", d.Block.NumberU64(), d.Block.Hash().Hex()[:9])))
				}
			},
		},
	},
	{
		eventT: logEventHeaderChainInsert,
		ev:     core.HeaderChainInsertEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case core.HeaderChainInsertEvent:
					glog.D(logger.Info).Infof(headerIcon+" Insert "+logger.ColorGreen("headers")+"=%s "+logger.ColorGreen("❐")+"=%s"+logger.ColorGreen("took")+"=%s",
						greenParenify(fmt.Sprintf("processed=%4d ignored=%4d", d.Processed, d.Ignored)),
						greenParenify(fmt.Sprintf("n=%4d hash=%s…", d.LastNumber, d.LastHash.Hex()[:9])),
						greenParenify(fmt.Sprintf("%v", d.Elasped.Round(time.Microsecond))),
					)
					if bool(glog.D(logger.Info)) {
						chainEventLastSent = time.Now()
					}
				}
			},
		},
	},
	{
		eventT: logEventMinedBlock,
		ev:     core.NewMinedBlockEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case core.NewMinedBlockEvent:
					glog.D(logger.Info).Infof(minedIcon + " Mined " + logger.ColorGreen("◼") + "=" + greenParenify(fmt.Sprintf("n=%8d hash=%s… coinbase=%s… txs=%3d uncles=%d",
						d.Block.NumberU64(),
						d.Block.Hash().Hex()[:9],
						d.Block.Coinbase().Hex()[:9],
						len(d.Block.Transactions()),
						len(d.Block.Uncles()),
					)))
				}
			},
		},
	},
	{
		eventT: logEventDownloaderStart,
		ev:     downloader.StartEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case downloader.StartEvent:
					s := downloaderIcon + " Start " + greenParenify(fmt.Sprintf("%s", d.Peer)) + " hash=" + greenParenify(d.Hash.Hex()[:9]+"…") + " TD=" + greenParenify(fmt.Sprintf("%v", d.TD))
					glog.D(logger.Info).Warnln(s)
				}
			},
		},
	},
	{
		eventT: logEventDownloaderDone,
		ev:     downloader.DoneEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case downloader.DoneEvent:
					s := downloaderIcon + " Done  " + greenParenify(fmt.Sprintf("%s", d.Peer)) + " hash=" + greenParenify(d.Hash.Hex()[:9]+"…") + " TD=" + greenParenify(fmt.Sprintf("%v", d.TD))
					glog.D(logger.Info).Warnln(s)
				}
			},
		},
	},
	{
		eventT: logEventDownloaderFailed,
		ev:     downloader.FailedEvent{},
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				switch d := evData.(type) {
				case downloader.FailedEvent:
					s := downloaderIcon + " Fail  " + greenParenify(fmt.Sprintf("%s", d.Peer)) + " " + logger.ColorRed("err") + "=" + redParenify(d.Err.Error())
					glog.D(logger.Info).Warnln(s)
				}
			},
		},
	},
	{
		eventT: logEventInterval,
		handlers: displayEventHandlerFns{
			func(ctx *cli.Context, e *eth.Ethereum, evData interface{}, tickerInterval time.Duration) {
				if time.Since(chainEventLastSent) > time.Duration(time.Second*time.Duration(int32(tickerInterval.Seconds()/2))) {
					currentBlockNumber = PrintStatusGreen(e, tickerInterval, ctx.GlobalInt(aliasableName(MaxPeersFlag.Name, ctx)))
				}
			},
		},
	},
}

// PrintStatusGreen implements the displayEventHandlerFn interface
var PrintStatusGreen = func(e *eth.Ethereum, tickerInterval time.Duration, maxPeers int) uint64 {
	lenPeers := e.Downloader().GetPeers().Len()

	rtt, ttl, conf := e.Downloader().Qos()
	confS := fmt.Sprintf("%01.2f", conf)
	qosDisplay := fmt.Sprintf("rtt=%v ttl=%v conf=%s", rtt.Round(time.Millisecond), ttl.Round(time.Millisecond), confS)

	_, current, height, _, _ := e.Downloader().Progress() // origin, current, height, pulled, known
	mode := e.Downloader().GetMode()
	if mode == downloader.FastSync {
		current = e.BlockChain().CurrentFastBlock().NumberU64()
	}

	// Get our head block
	blockchain := e.BlockChain()
	currentBlockHex := blockchain.CurrentBlock().Hash().Hex()

	// Discover -> not synchronising (searching for peers)
	// FullSync/FastSync -> synchronising
	// Import -> synchronising, at full height
	fOfHeight := fmt.Sprintf("%7d", height)

	// Calculate and format percent sync of known height
	heightRatio := float64(current) / float64(height)
	heightRatio = heightRatio * 100
	fHeightRatio := fmt.Sprintf("%4.2f%%", heightRatio)

	// Wait until syncing because real dl mode will not be engaged until then
	if currentMode == lsModeImport {
		fOfHeight = ""    // strings.Repeat(" ", 12)
		fHeightRatio = "" // strings.Repeat(" ", 7)
	}
	if height == 0 {
		fOfHeight = ""    // strings.Repeat(" ", 12)
		fHeightRatio = "" // strings.Repeat(" ", 7)
	}

	// Calculate block stats for interval
	numBlocksDiff := current - currentBlockNumber
	numTxsDiff := 0
	mGas := new(big.Int)

	var numBlocksDiffPerSecond uint64
	var numTxsDiffPerSecond int
	var mGasPerSecond = new(big.Int)

	var dominoGraph string
	var nDom int
	if numBlocksDiff > 0 && numBlocksDiff != current {
		for i := currentBlockNumber + 1; i <= current; i++ {
			b := blockchain.GetBlockByNumber(i)
			if b != nil {
				txLen := b.Transactions().Len()
				// Add to tallies
				numTxsDiff += txLen
				mGas = new(big.Int).Add(mGas, b.GasUsed())
				// Domino effect
				if currentMode == lsModeImport {
					if txLen > len(dominoes)-1 {
						// prevent slice out of bounds
						txLen = len(dominoes) - 1
					}
					if nDom <= 20 {
						dominoGraph += dominoes[txLen]
					}
					nDom++
				}
			}
		}
		if nDom > 20 {
			dominoGraph += "…"
		}
	}
	dominoGraph = logger.ColorGreen(dominoGraph)

	// Convert to per-second stats
	// FIXME(?): Some degree of rounding will happen.
	// For example, if interval is 10s and we get 6 blocks imported in that span,
	// stats will show '0' blocks/second. Looks a little strange; but on the other hand,
	// precision costs visual space, and normally just looks weird when starting up sync or
	// syncing slowly.
	numBlocksDiffPerSecond = numBlocksDiff / uint64(tickerInterval.Seconds())

	// Don't show initial current / per second val
	if currentBlockNumber == 0 {
		numBlocksDiffPerSecond = 0
		numBlocksDiff = 0
	}

	// Divide by interval to yield per-second stats
	numTxsDiffPerSecond = numTxsDiff / int(tickerInterval.Seconds())
	mGasPerSecond = new(big.Int).Div(mGas, big.NewInt(int64(tickerInterval.Seconds())))
	mGasPerSecond = new(big.Int).Div(mGasPerSecond, big.NewInt(1000000))
	mGasPerSecondI := mGasPerSecond.Int64()

	// Format head block hex for printing (eg. d4e…fa3)
	cbhexstart := currentBlockHex[:9] // trim off '0x' prefix

	localHeadHeight := fmt.Sprintf("#%7d", current)
	localHeadHex := fmt.Sprintf("%s…", cbhexstart)
	peersOfMax := fmt.Sprintf("%2d/%2d peers", lenPeers, maxPeers)
	domOrHeight := fOfHeight + " " + fHeightRatio
	if len(strings.Replace(domOrHeight, " ", "", -1)) != 0 {
		domOrHeight = logger.ColorGreen("height") + "=" + greenParenify(domOrHeight)
	} else {
		domOrHeight = ""
	}
	var blocksprocesseddisplay string
	qosDisplayable := logger.ColorGreen("qos") + "=" + greenParenify(qosDisplay)
	if currentMode != lsModeImport {
		blocksprocesseddisplay = logger.ColorGreen("~") + greenParenify(fmt.Sprintf("%4d blks %4d txs %2d mgas  "+logger.ColorGreen("/sec"), numBlocksDiffPerSecond, numTxsDiffPerSecond, mGasPerSecondI))
	} else {
		blocksprocesseddisplay = logger.ColorGreen("+") + greenParenify(fmt.Sprintf("%4d blks %4d txs %8d mgas", numBlocksDiff, numTxsDiff, mGas.Uint64()))
		domOrHeight = dominoGraph
		qosDisplayable = ""
	}

	// Log to ERROR.
	headDisplay := greenParenify(localHeadHeight + " " + localHeadHex)
	peerDisplay := greenParenify(peersOfMax)

	modeIcon := logger.ColorGreen(lsModeIcon[currentMode])
	if currentMode == lsModeDiscover {
		// TODO: spin me
		modeIcon = lsModeDiscoverSpinners[0]
	}
	modeIcon = logger.ColorGreen(modeIcon)

	// This allows maximum user optionality for desired integration with rest of event-based logging.
	glog.D(logger.Warn).Infof("%s "+modeIcon+"%s %s "+logger.ColorGreen("✌︎︎︎")+"%s %s %s",
		currentMode, headDisplay, blocksprocesseddisplay, peerDisplay, domOrHeight, qosDisplayable)
	return current
}