5

I created a private testchain following an answer I was given to another question.

It works fine for the most part I've had issues using miner.start().

It takes a long time to start.

I'm surprised that in a private testchain, I run miner.start(1) (or miner.start() have done both) at 10:07:12 and it only starts mining at 10:13:01. What is the reason for this delay?

> miner.start(1)
INFO [08-06|10:07:12] Updated mining threads                   threads=1
INFO [08-06|10:07:12] Transaction pool price threshold updated price=18000000000
INFO [08-06|10:07:12] Starting mining operation 
null
> INFO [08-06|10:07:12] Commit new mining work                   number=3585 txs=1 uncles=0 elapsed=764.873µs
> eth.hashrate
6
> INFO [08-06|10:13:01] Imported new chain segment               blocks=1 txs=1 mgas=0.021 elapsed=84.230ms  mgasps=0.249 number=3585 hash=3fac47…ee53b3
INFO [08-06|10:13:01] Commit new mining work                   number=3586 txs=0 uncles=0 elapsed=257.155µs
INFO [08-06|10:13:08] Imported new chain segment               blocks=1 txs=0 mgas=0.000 elapsed=24.286ms  mgasps=0.000 number=3586 hash=267b98…bef689
INFO [08-06|10:13:08] Commit new mining work                   number=3587 txs=0 uncles=0 elapsed=19.676ms
INFO [08-06|10:13:09] Successfully sealed new block            number=3587 hash=c53b0b…d8b6e5
INFO [08-06|10:13:09] 🔨 mined potential block                  number=3587 hash=c53b0b…d8b6e5
INFO [08-06|10:13:09] Commit new mining work                   number=3588 txs=0 uncles=0 elapsed=256.532µs
INFO [08-06|10:13:11] Imported new chain segment               blocks=1 txs=0 mgas=0.000 elapsed=4.807ms   mgasps=0.000 number=3588 hash=cb36ff…e6411b
INFO [08-06|10:13:11] Commit new mining work

... and sometimes it just doesn't seem to start

Though I reckon this could be just me not waiting long enough (thought I'd mention it anyway).

miner.start() returns null

Seems to be normal according to this and this answers but it only started happening recently so I don't really understand that. I should add that running eth.hashrate does return an int larger than 0.

EDIT: I asked this question a while ago but today I had

> INFO [08-16|11:59:28] Commit new mining work number=6525 txs=0 uncles=0 elapsed=233.189µs

It's now 12:25 and the miner hasn't started. There is no way this can be normal and I still don't understand how to fix it (to my complete desperation).

The debug output when the miner starts is

INFO [08-16|12:29:48] Updated mining threads                   threads=1
INFO [08-16|12:29:48] Transaction pool price threshold updated price=18000000000
INFO [08-16|12:29:48] Starting mining operation 
INFO [08-16|12:29:48] Commit new mining work                   number=6525 txs=0 uncles=0 elapsed=254.716µs
DEBUG[08-16|12:29:50] Adding p2p peer                          id=3f1d12044546b763 name=Geth/v1.6.5-stable-c... addr=13.93.211.84:30303 peers=2
DEBUG[08-16|12:29:50] Ethereum peer connected                  id=3f1d12044546b763 conn=dyndial name=Geth/v1.6.5-stable-cf87713d/linux-amd64/go1.7
DEBUG[08-16|12:29:50] Ethereum handshake failed                id=3f1d12044546b763 conn=dyndial err=EOF
DEBUG[08-16|12:29:50] Removing p2p peer                        id=3f1d12044546b763 conn=dyndial duration=220.044ms peers=1 req=true err="too many peers"
DEBUG[08-16|12:29:51] Adding p2p peer                          id=9f3c5c9323dfd48d name=Parity/v1.4.10-stabl...                       addr=172.104.73.213:30304 peers=2
DEBUG[08-16|12:29:51] Ethereum peer connected                  id=9f3c5c9323dfd48d conn=dyndial name=Parity/v1.4.10-stable-4e6329a-20170118/x86_64-linux-gnu/rustc1.15.0
DEBUG[08-16|12:29:51] Ethereum handshake failed                id=9f3c5c9323dfd48d conn=dyndial err=EOF
DEBUG[08-16|12:29:51] Removing p2p peer                        id=9f3c5c9323dfd48d conn=dyndial duration=248.010ms peers=1 req=true err="too many peers"
DEBUG[08-16|12:29:51] NTP sanity check done                    drift=-84.768453ms
DEBUG[08-16|12:29:52] Adding p2p peer                          id=62281146cb3ad611 name=Parity/v1.6.6-beta-8...                                             addr=37.187.119.202:30303 peers=2
DEBUG[08-16|12:29:52] Ethereum peer connected                  id=62281146cb3ad611 conn=dyndial name=Parity/v1.6.6-beta-8c6e3f3-20170411/x86_64-linux-gnu/rustc1.16.0
DEBUG[08-16|12:29:52] Ethereum handshake failed                id=62281146cb3ad611 conn=dyndial err=EOF
DEBUG[08-16|12:29:52] Removing p2p peer                        id=62281146cb3ad611 conn=dyndial duration=355.403ms peers=1 req=true err="too many peers"
DEBUG[08-16|12:29:53] Bad discv4 packet                        addr=141.105.132.110:30303 err="bad hash"
DEBUG[08-16|12:29:57] Adding p2p peer                          id=2dd1adfedadfb2f0 name=Geth/v3.4.0/linux/go...                                             addr=88.99.199.93:30303    peers=2
DEBUG[08-16|12:29:57] Ethereum peer connected                  id=2dd1adfedadfb2f0 conn=dyndial name=Geth/v3.4.0/linux/go1.8
DEBUG[08-16|12:29:57] Ethereum handshake failed                id=2dd1adfedadfb2f0 conn=dyndial err="Genesis block mismatch - d4e56740f876aef8 (!= dd3f8d61f38ebc19)"
DEBUG[08-16|12:29:57] Removing p2p peer                        id=2dd1adfedadfb2f0 conn=dyndial duration=122.937ms peers=1 req=true err="subprotocol error"
DEBUG[08-16|12:29:59] Recalculated downloader QoS values       rtt=20s confidence=1.000 ttl=1m0s
DEBUG[08-16|12:30:00] Adding p2p peer                          id=6b33cf1ee469e132 name=Geth/v1.6.1-stable-0...                                             addr=107.170.198.120:30303 peers=2
DEBUG[08-16|12:30:00] Ethereum peer connected                  id=6b33cf1ee469e132 conn=dyndial name=Geth/v1.6.1-stable-021c3c28/linux-amd64/go1.8.1
DEBUG[08-16|12:30:00] Ethereum handshake failed                id=6b33cf1ee469e132 conn=dyndial err=EOF
DEBUG[08-16|12:30:00] Removing p2p peer                        id=6b33cf1ee469e132 conn=dyndial duration=249.993ms peers=1 req=true err="subprotocol error"
DEBUG[08-16|12:30:08] Adding p2p peer                          id=c924d3b4f6c0cbac name=Geth/v1.5.8-unstable...                                             addr=88.99.99.100:30000    peers=2
DEBUG[08-16|12:30:08] Ethereum peer connected                  id=c924d3b4f6c0cbac conn=dyndial name=Geth/v1.5.8-unstable-690f6ea1/linux/go1.6.2
DEBUG[08-16|12:30:08] Adding p2p peer                          id=e4f43671b83d978d name=Parity/v1.6.8-beta-c...                                             addr=185.48.248.212:30303  peers=3
Improve this question
4
  • Yes, returning null is normal. Probably before mining kicked in so quickly that you didn't notice it. In your case what is puzzling is how at 10:07 it is working on Block 3585, but the first block that is actually mined is 3587. The delay looks to with "Imported new chain segment". Do you have any other nodes in your network? Could be worth temporarily increasing verbosity e.g. paste the following into one line to mine 3 blocks with DEBUG on: debug.verbosity(4);miner.start(1);admin.sleepBlocks(3);miner.stop();debug.verbosity(3);
    – Alan Buxton
    Aug 6, 2017 at 12:28
  • Hey @mcansado did you run that command to see what the debug output is when you start mining? It would be useful if you could share it here.
    – Alan Buxton
    Aug 8, 2017 at 2:12
  • Sorry this went under my radar! I've edited the question and yes I have one more node. Let me know if you need more info.
    – mcansado
    Aug 16, 2017 at 11:32
  • Hey @mcansado what does your log give you up to the point that the miner starts? Is it just the msg at 11:59 and then at 12:29 or is there anything in between those times?
    – Alan Buxton
    Aug 22, 2017 at 21:31

1 Answer 1

Reset to default
1

Short answer:

Yes, it's normal having to wait.

More detailed: When starting to mine, your computer needs time to generate the Ethash DAG. If you increase the logging verbosity of your node's console, you should see information on that.

As long as you see mined Ether dripping into your account and miner.hashrate shows a number > 0 everything is fine for you.

Improve this answer
3
  • DAG creation would show up with INFO logging on so I doubt it's that in this case: INFO [08-06|13:29:42] Generating DAG in progress epoch=0 percentage=0 elapsed=4.834s INFO [08-06|13:29:47] Generating DAG in progress epoch=0 percentage=1 elapsed=9.689s
    – Alan Buxton
    Aug 6, 2017 at 12:30
  • Thanks for the reply. I've seen it generated the DAG but was under the impression that was done once. From the link you shared that seems to be the case too because it's cached so the first time should take a while but not the ones after that. Is my thinking correct? Also, why did it start to return null when it didn't before?
    – mcansado
    Aug 7, 2017 at 9:42
  • 1
    Altough many people encounter the null response on the net, there doesn't seem to be a definite answer. And yes, it's supposed to be cached, but for me it's also often times generated over and over again - who knows why.
    – n1cK
    Aug 7, 2017 at 22:03

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.