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
Best Answer
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.