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

Improve status log #127

Closed
splix opened this issue Feb 3, 2017 · 11 comments
Closed

Improve status log #127

splix opened this issue Feb 3, 2017 · 11 comments

Comments

@splix
Copy link
Contributor

splix commented Feb 3, 2017

Currently geth has non-informative log, displaying download status only every 2048 blocks, which can take several hours per log line for block range 2,4xx,xxx.

It's better to display status every 1 minute, with details similar to Parity's. Suggested log is:

2017-02-03 16:49:00  Sync   #3124227 of #3124363 c76c…34e7   77/ 242/ 7 blk/tx/mgas sec    1/ 4/25 peers
2017-02-03 16:50:00  Sync   #3124247 of #3124363 75e4…8eff   51/  51/ 5 blk/tx/mgas sec    1/ 4/25 peers
2017-02-03 16:51:00  Sync   #3124567 of #3124363 9af3…34ae  117/ 129/11 blk/tx/mgas sec    2/ 5/25 peers
2017-02-03 16:52:00  Sync   #3124787 of #3124363 1e3a…8351    9/   6/ 1 blk/tx/mgas sec    1/ 7/25 peers
2017-02-03 16:52:05  Import #3124788             84e1…1ff4        15/ 7 tx/mgas            3/10/25 peers
2017-02-03 16:52:25  Import #3124789             9e45…a241         5/ 1 tx/mgas            5/12/25 peers
2017-02-03 16:52:45  Import #3124790             d819…f71c         0/ 0 tx/mgas           11/18/25 peers

Where:

  • Fast/Sync for initial sync, Import after that
  • #3124787 of #3124363 - block X of total height Y
  • c76c…34e7 block hash
  • 77/ 242/ 7 blk/tx/mgas sec performance for past minute, avg blocks/transactions/mgas processed per second. 3 character for block, 4 for transactions, 2 for mgas
  • 1/ 4/25 peers download from 1 peer, connected to 4, of max 25. 2 characters for each part
@splix splix added this to the Multi Chain milestone Feb 3, 2017
@splix splix assigned ghost Mar 31, 2017
@ghost ghost removed their assignment Mar 31, 2017
@whilei
Copy link
Contributor

whilei commented May 2, 2017

Also TODO:

Use glog package to modularize geth output logging to centralize control over formatting, verbosity. As is assorted logging methods, ie fmt and log are used seemingly randomly.

@splix
Copy link
Contributor Author

splix commented May 5, 2017

Now I think this task is bigger that we expected, let's move it to a next release?

@whilei whilei modified the milestones: Monetary Policy (public), Multi Chain May 5, 2017
@splix splix removed size/L labels Jul 26, 2017
@splix splix removed this from the Monetary Policy (public) milestone Jul 26, 2017
whilei added a commit to whilei/go-ethereum that referenced this issue Jul 27, 2017
solution: use a go func connected to the node's Ethereum to grab and calculate relevant logs

rel ethereumproject#127

---

TODO: fix or remove:
- downloading-from peers, eg 'this var/x/x peers'
- shows mode 'FullSync' before downloader initializes, even if it will be 'FastSync'
whilei added a commit to whilei/go-ethereum that referenced this issue Jul 27, 2017
solution: use a go func connected to the node's Ethereum to grab and calculate relevant logs

rel ethereumproject#127

---

TODO: fix or remove:
- downloading-from peers, eg 'this var/x/x peers'
- shows mode 'FullSync' before downloader initializes, even if it will be 'FastSync'
whilei added a commit to whilei/go-ethereum that referenced this issue Jul 27, 2017
solution: use a go func connected to the node's Ethereum to grab and calculate relevant logs

rel ethereumproject#127
rel ethereumproject#318

---

TODO: fix or remove:
- downloading-from peers, eg 'this var/x/x peers'
- shows mode 'FullSync' before downloader initializes, even if it will be 'FastSync'
whilei added a commit to whilei/go-ethereum that referenced this issue Jul 28, 2017
solution:
- remove dead code, old notes
- remove units from --log-pace= argument, just use seconds as value (simpler is better)
- if mining, show STATUS MINE with minerthreads and hashrate (TODO: more?)
- gofmt

Rel ethereumproject#127, ethereumproject#318
whilei added a commit that referenced this issue Aug 16, 2017
Creates option '--log-status="sync=<num seconds>". Also refactors existing geth commands to own file.

----

__Squash history__:

* sketches for using API for logging... may be overkill

may be worth thinking about more flexible and beautiful
ways to display information... 'monitor', 'attach', etc,
along with termui, graphs...

output can be 'machiney'-- line-by-line,
or human-y -- pictures of buffalo and whatnot.

* 💾

* WIP: problem: should implement interval-based status logging

solution: use a go func connected to the node's Ethereum to grab and calculate relevant logs

rel #127
rel #318

---

TODO: fix or remove:
- downloading-from peers, eg 'this var/x/x peers'
- shows mode 'FullSync' before downloader initializes, even if it will be 'FastSync'

* problem: no reason to force RPC

solution: comment code and include small explanation

* problem: no reason to return eth from StartNode

solution: remove exploratory code that is not useless

* problem: warning log should use logger.Warn

solution: move to Warn from Error

* problem: log-pace flag usage antiquated

solution: update it and simplify

* problem: should polish log-pace function

solution:
- remove dead code, old notes
- remove units from --log-pace= argument, just use seconds as value (simpler is better)
- if mining, show STATUS MINE with minerthreads and hashrate (TODO: more?)
- gofmt

Rel #127, #318

* problem: minor variable renaming and comments

solution: improve legibility

* problem: logging genesis account balances on Core log-level is too high

solution: relegate to debug

* problem: can share interrupt chan

solution: share chan in main between shutdown and closing status log goroutine

* problem: logging to dir should also output to stderr

solution: implement and glog SetAlsoToStdErr exported function and use in case of --log-dir

* problem: log io flush never called after interrupt

results in missing any logs after shutdown processes in FS logs

solution: defer log Flush after shutdown services

also decrease flushInterval from 30 -> 5 seconds (rate at which log buffer is written to FS)

* problem: rename '--log-pace' to '--log-status'

solution: rename flag and flagvar and status log function

also adds logstatus flag to correct category for usage output

* problem: want --log-status to be extensible for other interfaces

solution: refactor to use '--log-status='sync=60'' syntax, which can eventually support other features besides 'sync',
eg. mine, net, disk

* problem: (nonfunctional,refactor) should move cmd-oriented functions to cmd.go

solution: cut and paste and update imports

* solution: run gofmt

* problem: rollback command logging confirmation should check fastblock

solution: error if neither fastblock nor fullblock match desired head number

fixes #325

* problem: interrupt shutdown processes not consistent

solution: don't share os-interrupt channel as a global.
Notify library documentation clearly says Notify events can be called
multiple times and notification will be copied, so there's no harm in
listening for the same event on mutliple channels.

This pattern avoids a global and encourages per-feature handling of
shutdown scenarios.

* problem: (log syntax) log-status interval initial log still shows 'log-pace' wording

solution: fix
@whilei
Copy link
Contributor

whilei commented Sep 11, 2017

Closing via #324

@whilei whilei closed this as completed Sep 11, 2017
@splix splix reopened this Nov 21, 2017
@splix
Copy link
Contributor Author

splix commented Nov 21, 2017

  1. should work by default, not because of special command line option. also, wasn't able to enable it on linux, works only on macos
  2. prefix like I1120 22:49:30.038282 cmd/geth/cmd.go:929] doesn't make any sense, timestamp is enough
  3. just Sync not STATUS SYNC FullSync
  4. let's avoid (49.76%), takes space for no reason
  5. doesn't look like it shows progress, just stuck on same block
  6. I see some weird trace-level logs in addition to status output. shouldn't be here

@whilei
Copy link
Contributor

whilei commented Nov 23, 2017

  1. It works for me on linux:
freyabison@ribbon:~/geth $ ./geth --cache 5 --no-discover --max-peers=0 --log-status="sync=10" --verbosity 2
I1122 16:44:01.126103 cmd/geth/flag.go:421] WARNING: No etherbase set and no accounts found as default
I1122 16:44:01.132031 cmd/geth/flag.go:591] Machine logs: disabled
I1122 16:44:11.977780 cmd/geth/cmd.go:929] STATUS SYNC Discover #      0                     d4e…fa3    0/   0/ 0 blks/txs/mgas sec  0/ 0 peers
I1122 16:44:21.977749 cmd/geth/cmd.go:929] STATUS SYNC Discover #      0                     d4e…fa3    0/   0/ 0 blks/txs/mgas sec  0/ 0 peers
I1122 16:44:31.977801 cmd/geth/cmd.go:929] STATUS SYNC Discover #      0                     d4e…fa3    0/   0/ 0 blks/txs/mgas sec  0/ 0 peers
^CI1122 16:44:33.351044 cmd/geth/cmd.go:84] Got interrupt, shutting down...
freyabison@ribbon:~/geth $ geth version
-bash: geth: command not found
freyabison@ribbon:~/geth $ ./geth version
Geth
Version: v4.1.1+3-ca1f613
Protocol Versions: [63 62]
Network Id: 1
Go Version: go1.8
OS: linux
GOPATH=/home/freyabison/Go/imgopath
GOROOT=/home/freyabison/Go/imgroot/go

Maybe you can describe what you're seeing when not working for you on linux?

  1. Rel Remove rubbish from console out #410
  2. I used STATUS SYNC FullSync (which has alternate outputs as below):
STATUS SYNC FastSync
STATUS SYNC FullSync
STATUS SYNC Discover

because I anticipated that there may be other status logs that would eventually want to be included, like

STATUS PEER Discover
STATUS PEER SyncWith

STATUS MINE Mining
STATUS MINE Commit

STATUS STATE ValidateTx
STATUS STATE BroadcastTx

STATUS ACCOUNT Add
STATUS ACCOUNT Lock
  1. I find it useful to easily understand rate of progress without pulling out my calculator.
  2. It is based on a time intervals, not events, so if displayed statistics don't change within the interval it will appear static.

For example:

~/Library/EthereumClassic  ⟠ geth --chain mlogfly --log-status="sync=10" --verbosity 2 --log-dir mlogfly/log --port=30305
I1123 07:58:55.722680 cmd/geth/flag.go:421] WARNING: No etherbase set and no accounts found as default
I1123 07:58:55.723727 cmd/geth/flag.go:591] Machine logs: disabled
I1123 07:59:08.046853 cmd/geth/cmd.go:929] STATUS SYNC Discover # 254193                     450…2dd    0/   0/ 0 blks/txs/mgas sec  1/25 peers
I1123 07:59:18.048980 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 254208 of #4886528 (5.20%) cf6…ba6    1/   1/ 0 blks/txs/mgas sec  1/25 peers
I1123 07:59:28.163037 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 255018 of #4886528 (5.22%) 008…93f   81/ 156/ 4 blks/txs/mgas sec  1/25 peers
I1123 07:59:38.266593 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 256937 of #4886528 (5.26%) ab9…e35  191/ 164/ 3 blks/txs/mgas sec  1/25 peers
I1123 07:59:48.077975 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 257649 of #4886528 (5.27%) 5be…218   71/  80/ 1 blks/txs/mgas sec  2/25 peers
I1123 07:59:58.041863 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 257649 of #4886528 (5.27%) 5be…218    0/   0/ 0 blks/txs/mgas sec  2/25 peers
I1123 08:00:08.042088 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 257652 of #4886528 (5.27%) 803…c0b    0/   0/ 0 blks/txs/mgas sec  2/25 peers
I1123 08:00:18.346671 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 259197 of #4886528 (5.30%) df6…d55  154/ 114/ 6 blks/txs/mgas sec  2/25 peers
I1123 08:00:28.320982 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 260582 of #4886528 (5.33%) bf3…c79  138/ 196/ 4 blks/txs/mgas sec  2/25 peers
I1123 08:00:38.300362 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 262113 of #4886528 (5.36%) 176…ef5  153/ 116/ 2 blks/txs/mgas sec  2/25 peers

Perhaps this may be an opportunity to think about other STATUS log topics, as above, which would show progress if not necessarily block import/sync progress.

  1. You can adjust the general verbosity with --verbosity=n. --log-status currently uses Error verbosity, so
    in order to only view status logs and errors (which I expect anyone would want to see), you can use
--log-status="sync=10" --verbosity 1

One possible simple solve for your complaints would be to change the default settings for --verbosity, --vmodule, and --log-status. For example:

~/Library/EthereumClassic  ⟠ geth --log-status="sync=5" --verbosity 1 --vmodule="cmd/geth/*=3"
I1123 08:07:02.824060 cmd/geth/flag.go:816] --------------------------------------------------------------------------------------------------------------
~/Library/EthereumClassic  ⟠ geth --chain mlogfly --log-status="sync=5" --verbosity 1 --vmodule="cmd/geth/*=3" --log-dir mlogfly/log --port=30305
I1123 08:07:02.823363 cmd/geth/flag.go:813] Using custom chain configuration: mlogfly
I1123 08:07:02.824060 cmd/geth/flag.go:816] --------------------------------------------------------------------------------------------------------------
I1123 08:07:02.824085 cmd/geth/flag.go:818] Starting Geth Classic source.v4.1.1+20-d38a52e.mlog-block-difficulty.17-11-21-16-53-51
I1123 08:07:02.824103 cmd/geth/flag.go:819] Geth is configured to use ETC blockchain: Ethereum Classic Mainnet
I1123 08:07:02.824129 cmd/geth/flag.go:820] Using chain database at: /Users/ia/Library/EthereumClassic/mlogfly/chaindata
I1123 08:07:02.824143 cmd/geth/flag.go:822] 5 blockchain upgrades associated with this configuration:
I1123 08:07:02.824158 cmd/geth/flag.go:825]  1150000 Homestead
I1123 08:07:02.824196 cmd/geth/flag.go:825]  1920000 The DAO Hard Fork
I1123 08:07:02.824214 cmd/geth/flag.go:827]          with block 0x94365e3a8c0b35089c1d1195081fe7489b528a84b22199c916180db8b28ade7f
I1123 08:07:02.824223 cmd/geth/flag.go:825]  2500000 GasReprice
I1123 08:07:02.824235 cmd/geth/flag.go:825]  3000000 Diehard
I1123 08:07:02.824251 cmd/geth/flag.go:825]  5000000 Gotham
I1123 08:07:02.824276 cmd/geth/flag.go:838] State starting nonce: 0
I1123 08:07:02.824293 cmd/geth/flag.go:841] --------------------------------------------------------------------------------------------------------------
I1123 08:07:02.824505 cmd/geth/flag.go:421] WARNING: No etherbase set and no accounts found as default
I1123 08:07:02.824965 cmd/geth/flag.go:591] Machine logs: disabled
I1123 08:07:04.937583 cmd/geth/cmd.go:824] STATUS SYNC Log interval set: 5 seconds
I1123 08:07:09.939686 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  0/25 peers
I1123 08:07:14.938607 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  0/25 peers
I1123 08:07:19.942139 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  1/25 peers
I1123 08:07:24.938110 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  1/25 peers
I1123 08:07:29.938100 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  1/25 peers
I1123 08:07:34.936578 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  1/25 peers
I1123 08:07:39.937234 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:07:44.935521 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:07:49.936484 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:07:54.935826 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:07:59.936243 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:08:04.934568 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:08:09.937045 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:08:14.934633 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:08:19.935809 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  3/25 peers
I1123 08:08:24.932957 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:29.937011 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:34.932925 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:39.936670 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:44.931744 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:49.935026 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:54.932716 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:08:59.932219 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:04.931176 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:09.931392 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:14.930700 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:19.933474 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:24.930792 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:29.929252 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:34.928795 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:39.933029 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:44.929345 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:49.929425 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:54.927792 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:09:59.929695 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:10:04.927357 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:10:09.926970 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:10:14.928047 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:10:19.926908 cmd/geth/cmd.go:929] STATUS SYNC Discover # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  4/25 peers
I1123 08:10:24.926125 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 263107                     fcc…0b2    0/   0/ 0 blks/txs/mgas sec  5/25 peers
I1123 08:10:29.926513 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 263107 of #4886577 (5.38%) fcc…0b2    0/   0/ 0 blks/txs/mgas sec  7/25 peers
I1123 08:10:35.042953 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 263681 of #4886577 (5.40%) 0d7…883  114/  99/ 2 blks/txs/mgas sec  7/25 peers
I1123 08:10:39.972356 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 264259 of #4886577 (5.41%) ce5…ff5  115/  99/ 2 blks/txs/mgas sec  7/25 peers
I1123 08:10:44.925355 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 264259 of #4886577 (5.41%) ce5…ff5    0/   0/ 0 blks/txs/mgas sec  7/25 peers
I1123 08:10:49.932385 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 264475 of #4886577 (5.41%) 4d2…5f0   43/  46/ 1 blks/txs/mgas sec  7/25 peers
I1123 08:10:54.944456 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 264817 of #4886577 (5.42%) c0c…196   68/ 162/ 3 blks/txs/mgas sec  7/25 peers
I1123 08:11:00.149049 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 265444 of #4886577 (5.43%) 5e2…54a  125/ 210/ 4 blks/txs/mgas sec  7/25 peers
I1123 08:11:05.022771 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 266522 of #4886577 (5.45%) 2c7…842  215/ 138/ 3 blks/txs/mgas sec  7/25 peers
I1123 08:11:09.962473 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 267160 of #4886577 (5.47%) b67…406  127/ 140/ 3 blks/txs/mgas sec  7/25 peers
I1123 08:11:15.163243 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 267805 of #4886577 (5.48%) 2e1…9fc  129/ 275/ 9 blks/txs/mgas sec  7/25 peers
I1123 08:11:20.028177 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 268422 of #4886577 (5.49%) ea5…452  123/ 136/ 5 blks/txs/mgas sec  7/25 peers
I1123 08:11:25.337389 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 268860 of #4886577 (5.50%) cd3…501   87/  84/ 2 blks/txs/mgas sec  7/25 peers
I1123 08:11:30.043400 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 269366 of #4886577 (5.51%) b86…a33  101/  80/ 2 blks/txs/mgas sec  7/25 peers
I1123 08:11:35.052071 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 269842 of #4886577 (5.52%) 1ca…530   95/ 124/ 3 blks/txs/mgas sec  7/25 peers
I1123 08:11:40.037327 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 270229 of #4886577 (5.53%) 584…66e   77/ 261/ 6 blks/txs/mgas sec  7/25 peers
I1123 08:11:45.065795 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 270975 of #4886577 (5.55%) 800…589  149/ 117/ 4 blks/txs/mgas sec  6/25 peers
I1123 08:11:50.010407 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 271550 of #4886577 (5.56%) 7ec…75c  115/  74/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:11:55.033148 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 272152 of #4886577 (5.57%) 22b…c59  120/ 131/ 6 blks/txs/mgas sec  6/25 peers
I1123 08:12:00.010097 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 272250 of #4886577 (5.57%) e91…7ac   19/ 204/ 4 blks/txs/mgas sec  6/25 peers
I1123 08:12:05.075683 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 272664 of #4886577 (5.58%) cfe…fe3   82/ 109/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:10.146707 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 273200 of #4886577 (5.59%) 863…c83  107/ 117/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:15.113379 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 273846 of #4886577 (5.60%) f8f…0ff  129/ 125/ 4 blks/txs/mgas sec  6/25 peers
I1123 08:12:20.121088 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 274368 of #4886577 (5.61%) 268…e57  104/ 100/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:24.971454 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 274891 of #4886577 (5.63%) 9cc…38a  104/ 145/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:30.069639 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 275379 of #4886577 (5.64%) 01b…999   97/ 262/ 6 blks/txs/mgas sec  6/25 peers
I1123 08:12:35.045331 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 276243 of #4886577 (5.65%) 9f7…737  172/ 134/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:40.020919 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 276835 of #4886577 (5.67%) 998…a9f  118/ 100/ 3 blks/txs/mgas sec  6/25 peers
I1123 08:12:44.952155 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 277377 of #4886577 (5.68%) 171…c0e  108/ 144/ 5 blks/txs/mgas sec  6/25 peers
I1123 08:12:50.020155 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 277654 of #4886577 (5.68%) 600…abc   55/ 330/ 6 blks/txs/mgas sec  6/25 peers
I1123 08:12:55.304112 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 278837 of #4886577 (5.71%) d43…20b  236/ 246/ 6 blks/txs/mgas sec  6/25 peers
I1123 08:13:00.053138 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 279601 of #4886577 (5.72%) 4b7…4a5  152/ 167/ 4 blks/txs/mgas sec  7/25 peers
I1123 08:13:04.997850 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 280098 of #4886577 (5.73%) a36…136   99/ 128/ 3 blks/txs/mgas sec  7/25 peers
I1123 08:13:10.023077 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 280472 of #4886577 (5.74%) deb…428   74/ 245/ 5 blks/txs/mgas sec  8/25 peers
I1123 08:13:15.210155 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 281334 of #4886577 (5.76%) 9d9…bdd  172/ 127/ 3 blks/txs/mgas sec  8/25 peers
I1123 08:13:19.992672 cmd/geth/cmd.go:929] STATUS SYNC FullSync # 282313 of #4886577 (5.78%) f38…364  195/ 138/ 3 blks/txs/mgas sec 10/25 peers

@splix
Copy link
Contributor Author

splix commented Nov 23, 2017

  1. just nothing, looks like it stuck. tried few times, blank screen, or error logs if try to emulate network problems. so geth works, but doesn't give status feedback log
  2. there will be only sync and import in that status. it's not logs
  3. but it will always be 98% or 99%, except initial import, why? and if you need it, time in hours makes more sense during initial import, rather than percentage
  4. ah, I see, it was on STATUS SYNC Discover mode. I didn't plan Discover mode initially, only sync, so didn't realize it's not a sync. let's discuss it on separate ticket do we need discover feedback and if we need how it should look like (because current block num and blks/txs/mgas sec are definitely meaningless in that context)
  5. let's make good default output. users will never dig into command line options for that, they will quit instead

@splix
Copy link
Contributor Author

splix commented Dec 14, 2017

Updated

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

Where:

  • Fast/Sync for initial sync, Import after that, Discover on start
  • #3124787 of #3124363 - block X of total height Y
  • c76634e7 block hash
  • 77/ 242/ 7 blk/tx/mgas sec performance for past minute, avg blocks/transactions/mgas processed per second. 3 character for block, 4 for transactions, 2 for mgas
  • 4/25 peers connected to 4, of max 25. 2 characters for each part

@whilei
Copy link
Contributor

whilei commented Dec 14, 2017

So for all modes besides Import it should print status logs only every 1 minute, but for Import it should print a line for each block it imports (not time-interval based)?

And Import should not differentiate between canonical block insertions and forked block insertions? (So you could see 3124790 inserted twice with different hashes)? Or should be ONLY canonical insertions logged?

@whilei
Copy link
Contributor

whilei commented Dec 14, 2017

And are all error and warning logs entirely suppressed? I'm inclined to print both, and attention has been paid to sorting out warning/error/fatals so severities like error and fatal should be actually relevant

(Currently Error and Fatal logs will rise to stderr), with only Fatal logs printing stack traces, whereas Error logs print only Caller line traces.

Example (artificial) current error:

E1213 15:00:00.417481 eth/downloader/downloader:654] err: could not remove peer adsfasd212341234 (Peer not registered) 

Example current fatal:

F1213 15:00:00.417481 logger/glog/glog.go:1204] remove /Users/ia/Library/EthereumClassic/mainnet/log/geth.mh.ia.log.INFO.20171213-142408.9369: no such file or directory
goroutine 31349 [running]:
github.com/ethereumproject/go-ethereum/logger/glog.stacks(0xc420060200, 0xc42888cf00, 0xb2, 0x25e)
    /Users/ia/gocode/src/github.com/ethereumproject/go-ethereum/logger/glog/glog.go:1036 +0xcf
github.com/ethereumproject/go-ethereum/logger/glog.(*loggingT).output(0x50c7a20, 0xc400000003, 0xc4200826e0, 0x4fc017d, 0x13, 0x4b4, 0x0)
    /Users/ia/gocode/src/github.com/ethereumproject/go-ethereum/logger/glog/glog.go:987 +0x327
github.com/ethereumproject/go-ethereum/logger/glog.(*loggingT).printDepth(0x50c7a20, 0xc400000003, 0x1, 0xc425c37f70, 0x1, 0x1)

Also, @splix What are your reasons for showing mgas rate? I've never felt a burning desire to know mgas rate... is there a background or use for this?

@splix
Copy link
Contributor Author

splix commented Dec 14, 2017

Yes, for Import it should print it at the moment of import. Other statuses just aggregation, one per minute.

Errors/warning should be displayed in normal way, but we may want to reconsider what should be logged as error/warning. It's a separate issue

@whilei
Copy link
Contributor

whilei commented Jan 1, 2018

Closed with #423

@whilei whilei closed this as completed Jan 1, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

2 participants