Skip to content
This repository was archived by the owner on Oct 4, 2019. It is now read-only.

improve logging, separate display/debug logs #423

Merged
merged 65 commits into from
Jan 1, 2018
Merged

Conversation

whilei
Copy link
Contributor

@whilei whilei commented Dec 3, 2017

problem

Existing logging isn't as friendly-looking as it could be. The logs are purely event/protocol derived and include a lot of often-noisy information.

solution

Separate "debug"-y logs from "displayable" logs; ie end-user-facing vs. developer-facing. Base display logs not only on events (via mux subscriptions), but also on time-interval-based status logging.

The proposed solution:

  • modifies display log line formatting toward simplicity, consistency, and grouping related ideas (like block import statistics processed, ignored, queued, etc.). It also introduces thematic coloring, icon-ification for modes, events, and tallies.
  • collects all existing glog.V protocol/event logs to files in <chaindir>/log with default verbosity Debug. These files are then rotated automatically based on size and age.
  • introduces glog.D for logs which should only be rendered to stderr; these display logs are also verbosity-aware, and can be adjusted. Current default is --display=2 on a practical scale of 0(totally silent)-3(include event subscriptions), where 2 prints mostly only interval-based status logs (ala --log-status), like:
I1203 07:10:53 SYNC Import   ▶︎⟪#4950584 0xfca0d22…⟫ +⟪   4 blks   40 txs   893225 mgas⟫ ✌︎︎︎⟪12/25 peers⟫ 🂓🁥🁦🂓

while --display=3 includes subscription-based logs like

I1203 07:16:04 ◼⋯⋯◼ Insert blocks=⟪processed=   1 queued=   0 ignored=   0 txs=   0⟫ ◼=⟪n= 4950602 hash=0xb044b6d… time=54.083401725s ago⟫ took=⟪5.868158ms⟫
  • establishes default verbosity+severity thresholds enabling any existing severity=Error logs from glog.V to also be written to stderr, along with their file trace
  • introduces --neckbeard flag for developers who'd rather get all normal glog.V debug-y logs to stderr and don't like pretty colors

discussion

❓ Do we like the colors? Any suggestions, feedback, or wishes for the proposed formatting?
❓ Should we move default --display verbosity to 3 to also include subscription-based logs?

todo

  • include miner display logs
  • fix tests
  • write tests
  • ensure symbols/icons work on all os's

🖌 There's a lot of commits and they're pretty messy (not always problem/solution format, etc...). Will squash before merge, but left as-is for sake of transparency and granularity for now.

examples

ℹ️ Note in the screenshots the small terminal window below where tail is following the relevant debug log files (~/Library/EthereumClassic/mainnet/log/geth.INFO).

Current default: --display=3
screen shot 2017-12-03 at 07 24 29

--display=2
screen shot 2017-12-03 at 07 15 35

--neckbeard
screen shot 2017-12-03 at 07 25 53

iconography

Event logs have associated icons:

Downloader [Start|Done|Fail]: ◼⋯⋯⬇

I1203 07:48:39 ◼⋯⋯⬇ Start ⟪Peer id=3355c6b44e100a99 eth/63 [Parity/v1.8.1-beta-0e4a06d-20171020/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=⟪0x2d6e961…⟫ TD=⟪171941664579510193825⟫

BlockchainInsertBlocks: ◼⋯⋯◼

I1203 07:50:04 ◼⋯⋯◼ Insert blocks=⟪processed=   1 queued=   0 ignored=   0 txs=   7⟫ ◼=⟪n= 4950744 hash=0x1ffed1e… time=20.567166733s ago⟫ took=⟪27.439103ms⟫

BlockchainInsertForkedBlock: ◼⋯⦦◼

I1203 07:51:31 ◼⋯⦦◼ Insert forked block=⟪n= 4950749 hash=0x3776d82…⟫

HeaderchainInsertHeaders: ◼⋯⋯❐

I1203 07:58:11 ◼⋯⋯❐ Insert headers=⟪processed=2048 ignored=   0⟫ ❐=⟪n=8576 hash=0x0ddc763…⟫took=⟪433.059351ms⟫

MinedBlock: ◼⋯⋯⟠

I1206 08:25:17 ◼⋯⋯⟠ Mined ◼=⟪n=     139 hash=0xc08322b… coinbase=0x3d1cf2f… txs=  0 uncles=0⟫

SYNC logs have associated icons:

Discover: "spins" through {"➫", "➬", "➭"}

I1203 07:59:03 SYNC Discover ➫⟪#      0 0xd4e5674…⟫ ~⟪   0 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 0/25 peers⟫
I1203 07:59:33 SYNC Discover ➬⟪#      0 0xd4e5674…⟫ ~⟪   0 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 0/25 peers⟫
I1203 08:00:03 SYNC Discover ➭⟪#      0 0xd4e5674…⟫ ~⟪   0 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 1/25 peers⟫

FullSync:

I1203 08:02:33 SYNC FullSync ◉⟪#  33600 0x45b38c6…⟫ ~⟪  66 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 4/25 peers⟫

FastSync:

I1203 08:02:33 SYNC FastSync ◎⟪#  33600 0x45b38c6…⟫ ~⟪  66 blks    0 txs  0 mgas  /sec⟫ ✌︎︎︎⟪ 4/25 peers⟫ height=⟪4950785 0.68%⟫

Import (tracking at head):

I1203 07:53:31 SYNC Import   ▶︎⟪#4950761 0x6c9f16a…⟫ +⟪  18 blks  140 txs  3670871 mgas⟫ ✌︎︎︎⟪ 6/25 peers⟫ 🁼🁣🁦🂓🂌🁦🁣🁣🁣🂓🁥🁣🁴🁣🁴🁼🁣🁤

"Domino Effect": the number of dominos relates the number of blocks imported in the given period, while the number of dots on each domino correspond to the number of txs in each relative block. When the total number of blocks imported is greater than 20, a single ellipsis is added to prevent clogging the screen with possibly hundreds of dominos.


Rel issues logrotation: #421, noisy log lines: #410, general improve status log: #127
Rel milestone 4.2: https://github.com/ethereumproject/go-ethereum/milestone/12

@whilei whilei added this to the 4.2 - Improved usability milestone Dec 3, 2017
@whilei whilei force-pushed the feat/log-display branch 3 times, most recently from ae754c3 to 425f94d Compare December 6, 2017 15:35
solution:
create alternate loggingT instance, using glog.D (vs. glog.V)
update tests
colorize output respectively
ensure debug (glog.V) logs are still rendered in stderr with traces for severity=.Error
implement convenience colorizing methods
solution:
use display logs as default for stderr, sending glog.V logs to file
set global verbosity for glog.V -> logger.Debug (Level 5), noting that --verbosity flag can still override
use --neckbeard flag to enable sending debug logs to stderr INSTEAD of display logs
expose VerbosityTraceFloor as debug API <-- note: this to be REMOVED
solution:
able to provide rolling status logs at glog.D(logger.Warn) verbosity,
  and event logs for blockchain, headerchain, mining, and downloading
… display

solution: makes quite a few log lines better aware of verbosity and severity, so
errors use .Error, more important logs have verbosities Warn, etc.
add glog.D log lines for configuration notices, cmd progress reports, and other important HUD events
whilei added 14 commits December 6, 2017 12:19
making chainIsMorden fail when --testnet used

solution: refactor
solution: fix tests (adjust bats tests to new syntax/+logging cases

- move datadir schema migration logic to cli.Before because it
  requires that the default log directory (in datadir) have not
  been established when checking for non/existing datadirs.
and to be able to handle possibly unexpected edge cases better
this makes the default stderr logging show chain events like insert, download, and mine
in addition to rolling status logs by default
solution: remove flag and RPC method

This flag and method were used to be able to configure the trace level for
standard logging. With display/debug logs, there is little to no use for
adjusting the trace level for debug logs
solution: turn off testing.Log for visual checking of rewards
solution: toggle display logging for tests to 0 at init fn
solution: implement congruent test fns for display tests
and write a few display tests
solution: implement pattern to run tests which call glog.Fatal (ie os.Exit(1))
in separate process
solution: use filepath.Join for expected out
solution: add display log
Copy link
Contributor

@tzdybal tzdybal left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I found some small issues. I'll re-review this tomorrow with fresh mind.

cmd/geth/main.go Outdated
}
}
// Set default debug verbosity level.
glog.SetV(5)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This sets magic verbosity level (which by accident equals the default value) - please introduce constant.

cmd/geth/main.go Outdated
glog.SetToStderr(true)
// Turn verbosity down for migration check. If migration happens, it will print to Warn.
// Otherwise logs are just debuggers.
glog.SetV(3)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would extract this entire block between glog.SetVs to a separate function.

cmd/geth/main.go Outdated

// log.Println("Writing logs to ", logDir)
// Turn on only file logging, disabling logging(T).toStderr and logging(T).alsoToStdErr
glog.SetToStderr(false)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And move the entire logging configuration to separate file (probably after merging #426)

cmd/geth/main.go Outdated
// Set log dir.
// GOTCHA: There may be NO glog.V logs called before this is set.
// Otherwise everything will get all fucked and there will be no logs.
glog.SetLogDir(logDir)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Before glog.SetLogDir is called, logs are saved to system-default temporary directory. If logging is started before this call, the new logDir will be used after file rotation (by default after 1800MB of data per file).

@@ -530,7 +537,7 @@ func (self *BlockChain) LoadLastState(dryrun bool) error {
defer self.mu.Lock()

if recoveredHeight == 0 {
glog.V(logger.Warn).Infoln("WARNING: No recoverable data found, resetting to genesis.")
glog.V(logger.Error).Errorln("WARNING: No recoverable data found, resetting to genesis.")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why WARNING: from the message is not removed in all places?

glog.V(logger.Warn).Infof("Last block: #%d [%x…] TD=%v", self.currentBlock.Number(), self.currentBlock.Hash().Bytes()[:4], blockTd)
glog.V(logger.Warn).Infof("Fast block: #%d [%x…] TD=%v", self.currentFastBlock.Number(), self.currentFastBlock.Hash().Bytes()[:4], fastTd)
glog.D(logger.Warn).Infof("Local head header: #%s [%s…] TD=%s",
logger.ColorGreen(strconv.Itoa(int(self.hc.CurrentHeader().Number.Uint64()))),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of Itoa and type cast, you should use FormatUint

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note to self: still TODO.

Copy link
Contributor

@tzdybal tzdybal left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logging (or rather display) infrastructure is quite complicated after latest changes. But it gives great flexibility - dash is a perfect example.

I need some time running dashboard in real world to provide more comments about it's look and feel (first thought: I would love to see chain name somewhere).

I approve the PR. As dashboard is still experimental, I think time and feedback is needed to eventually improve the display.

if ctx.GlobalIsSet(DisplayFlag.Name) {
i := ctx.GlobalInt(DisplayFlag.Name)
if i > 5 {
return fmt.Errorf("--%s level must be 0 <= i <= 3, got: %d", DisplayFlag.Name, i)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

0 <= i <= 5, not <= 3


if logger.MlogEnabled() {
glog.V(logger.Warn).Warnf("Machine log config: mlog=%s mlog-dir=%s", logger.GetMLogFormat().String(), logger.GetMLogDir())
glog.D(logger.Warn).Infof("Machine log config: mlog=%s mlog-dir=%s", logger.ColorGreen(logger.GetMLogFormat().String()), logger.ColorGreen(logger.GetMLogDir()))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This Infof seems inconsistent with other Warnfs.

// displayEventHandlers set. This can be considered a temporary solve for handling "registering" or
// "delegating" log interface systems.
func mustGetDisplaySystemFromName(s string) displayEventHandlers {
displaySystem := basicDisplaySystem
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's more "idiomatic" to write this without variable, returning from each case, and fataling by default. But it's just a cosmetic change, and I'm not sure which solution is more clear ;)

}
}
if len(eqs) < 2 {
glog.Errorf("%v: %v. Must be comma-separated pairs of module=interval.", ErrInvalidFlag, eqs)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why Error->os.Exit instead of Fatalf?

}

// Examples of spec'd output.
var xlocalOfMaxD = "#92481951 of #93124363" // #2481951 of #3124363
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It looks like const, not var. Consider using block, instead of individual consts/vars.

"github.com/ethereumproject/go-ethereum/logger"
"github.com/ethereumproject/go-ethereum/core"
"fmt"
)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Comment with example "display" is a nice feature of default display format. For "prettier" logging, comments may contain colorless transcript of a display.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done.

return sl
}

// greenDisplaySystem is "spec'd" in PR #423 and is a little fancier/more detailed and colorful than basic.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy-pasted comment, please update or remove.

}
DisplayFormatFlag = cli.StringFlag{
Name: "display-fmt",
Usage: "Display format",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please add information about possible values (default, dash and green).

@splix
Copy link
Contributor

splix commented Dec 19, 2017

Looks great!
Can we align all units to (by tx/mgas):

2017-02-03 16:44:00  Discover                                                              0/25 peers
2017-02-03 16:45:00  Discover                                                              1/25 peers
2017-02-03 16:46:00  Fast   #2481951 of #3124363    79.4%   1211/  554    blk/mgas sec     6/25 peers
2017-02-03 16:47:00  Fast   #2689911 of #3124363    86.1%    611/  981    blk/mgas sec     6/25 peers
2017-02-03 16:48:00  Fast   #2875913 of #3124363    92.0%    502/  760    blk/mgas sec     4/25 peers
2017-02-03 16:49:00  Sync   #3124227 of #3124363 c76c34e7   77/ 242/ 7 blk/tx/mgas sec     4/25 peers
2017-02-03 16:50:00  Sync   #3124247 of #3124363 75e48eff   51/  51/ 5 blk/tx/mgas sec     4/25 peers
2017-02-03 16:51:00  Sync   #3124567 of #3124363 9af334ae  117/ 129/11 blk/tx/mgas sec     5/25 peers
2017-02-03 16:52:00  Sync   #3124787 of #3124363 1e3a8351    9/   6/ 1 blk/tx/mgas sec     7/25 peers
2017-02-03 16:52:05  Import #3124788             84e11ff4        15/ 7     tx/mgas        10/25 peers
2017-02-03 16:52:25  Import #3124789             9e45a241         5/ 1     tx/mgas        12/25 peers
2017-02-03 16:52:45  Import #3124790             d819f71c         0/ 0     tx/mgas        18/25 peers
2017-02-03 16:52:46  Mined  #3124791             b719f31b         7/ 1     tx/mgas        18/25 peers

or to (left):

2017-02-03 16:44:00  Discover                                                              0/25 peers
2017-02-03 16:45:00  Discover                                                              1/25 peers
2017-02-03 16:46:00  Fast   #2481951 of #3124363    79.4%   1211/  554 blk/mgas sec        6/25 peers
2017-02-03 16:47:00  Fast   #2689911 of #3124363    86.1%    611/  981 blk/mgas sec        6/25 peers
2017-02-03 16:48:00  Fast   #2875913 of #3124363    92.0%    502/  760 blk/mgas sec        4/25 peers
2017-02-03 16:49:00  Sync   #3124227 of #3124363 c76c34e7   77/ 242/ 7 blk/tx/mgas sec     4/25 peers
2017-02-03 16:50:00  Sync   #3124247 of #3124363 75e48eff   51/  51/ 5 blk/tx/mgas sec     4/25 peers
2017-02-03 16:51:00  Sync   #3124567 of #3124363 9af334ae  117/ 129/11 blk/tx/mgas sec     5/25 peers
2017-02-03 16:52:00  Sync   #3124787 of #3124363 1e3a8351    9/   6/ 1 blk/tx/mgas sec     7/25 peers
2017-02-03 16:52:05  Import #3124788             84e11ff4        15/ 7 tx/mgas            10/25 peers
2017-02-03 16:52:25  Import #3124789             9e45a241         5/ 1 tx/mgas            12/25 peers
2017-02-03 16:52:45  Import #3124790             d819f71c         0/ 0 tx/mgas            18/25 peers
2017-02-03 16:52:46  Mined  #3124791             b719f31b         7/ 1 tx/mgas            18/25 peers

it seems that second option is more logical and more flexible for extensions

- adds commented examples for display fmts
- moves a few vars to block consts
- use glog.Fatal instead of glog.Err + os.Exit
- fix typos and deadness in comments
- make a few logs more consistent
solution: refactors log_display_basic, adds handler for mined block event

- also debugs print basic trying to calc diff for whole chain
use global 'current' bookmark vars instead of local copies
check that we're not going to try and calc progress rate for whole chain
solution: reorg mode decision logic
@whilei
Copy link
Contributor Author

whilei commented Dec 19, 2017

screen shot 2017-12-19 at 13 48 58

@whilei
Copy link
Contributor Author

whilei commented Dec 20, 2017

FYI -- waiting on rustup brokennes rust-lang/rustup#1316

ellaismer added a commit to ellaism/go-ellaism that referenced this pull request Dec 29, 2017
@splix
Copy link
Contributor

splix commented Dec 30, 2017

@whilei tested with last changes, looks really good now.

The only thing I've noticed is that it put duplicate lines sometimes:

2017-12-30 17:40:52 Import    #5112945              21096f96          1/ 0 txs/mgas         12/25 peers
2017-12-30 17:40:53 Import    #5112945              21096f96          6/ 0 txs/mgas         12/25 peers
...
2017-12-30 17:43:45 Import    #5112955              0a128794          8/ 0 txs/mgas         13/25 peers
2017-12-30 17:43:46 Import    #5112955              0a128794          5/ 0 txs/mgas         13/25 peers
...
2017-12-30 17:44:42 Import    #5112959              93acc208         18/ 0 txs/mgas         13/25 peers
2017-12-30 17:44:43 Import    #5112959              93acc208          0/ 0 txs/mgas         13/25 peers

It looks strange, especially the fact that block hash is same, but number of transactions is different.

@splix
Copy link
Contributor

splix commented Dec 30, 2017

Also, when it imports few blocks at once, let's add number of additional blocks, like:

2017-12-30 22:11:42 Import    #5114110              a2faa651          3/ 0 txs/mgas         13/25 peers
2017-12-30 22:12:39 Import    #5114113 (+2)         efe9500b          0/ 0 txs/mgas         12/25 peers

and make sure that txs/mgas for multiple blocks is sum over these blocks

@whilei whilei changed the title [WIP-feedbackwanted] improve logging, separate display/debug logs improve logging, separate display/debug logs Dec 30, 2017
solution: use event block data instead of db currentblock for import log
solution: pass event to print fn instead of block,
improve logic around bookmark current head printed and to-print block
solution: add display line for interrupt signal
@whilei
Copy link
Contributor Author

whilei commented Dec 30, 2017

@splix Just pushed a few changes addressing your notes above.

I set the (+2) to be (+ 2) (2-digit padded), since that should cover most cases. The only exception is the first Import line because it will have just entered "Insert mode" and will reflect the last chain-insert batch. There is example of this below at the (+217) line. I don't like that the spacing looks weird for this case, but maybe not worth the code complexity it would take to change it. Or we could just set it to be 4-digit padded and everything would always line up, but there will often be 2 or 3 spaces of empty padding, like (+___3)
I just pushed it to be 4-digit padded. I think it's cleaner that way.

screen shot 2017-12-30 at 16 04 57

Updated:

screen shot 2017-12-30 at 16 24 38

solution: make it 4-digit padded for consistency
across all possible cases
@whilei whilei merged commit 844bb48 into master Jan 1, 2018
@whilei whilei deleted the feat/log-display branch January 1, 2018 15:45
This was referenced Jan 1, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants