hangs on startup #3004

ghost commented at 9:28 PM on September 16, 2013: none

After updating to latest git version about a month ago, bitcoind always hangs on startup. After attempting to connect to nodes, it just stops doing anything except flushing peers.dat periodically. Issued rpc commands also just hang. There's no cpu or disk activity related to bitcoind. The only way to get it to start properly is to use -rescan, but that's not a practical long-term solution because it literally takes days for my slow hard drive to rescan the blockchain. The daemon was safely closed with with bitcoind stop prior to the restart and I haven't seen log messages relating to corruption. I have also kept updating to git head after every version to see if the problem resolves. In this state bitcoind stop also hangs.

I'm going to try to finding the last working version that didn't exhibit this problem, but that's probably going to take a while and I'm hoping somebody will have ideas before then.

Running on OSX 10.7.5.

My bitcoind.conf:

checklevel=2
listen=0
dns=1
server=1
rpcuser=xxx
rpcpassword=xxx

The debug log:

2013-09-16 20:34:46 Bitcoin version v0.8.0-734-ga25cd0b-beta (2013-09-16 06:25:12 -0700)
2013-09-16 20:34:46 Using OpenSSL version OpenSSL 1.0.1e 11 Feb 2013
2013-09-16 20:34:46 Default data directory /Users/xxx/Library/Application Support/Bitcoin
2013-09-16 20:34:46 Using data directory /Users/xxx/Library/Application Support/Bitcoin
2013-09-16 20:34:46 Using at most 125 connections (275 file descriptors available)
2013-09-16 20:34:46 Using 2 threads for script verification
2013-09-16 20:34:46 init message: Verifying wallet...
2013-09-16 20:34:46 dbenv.open LogDir=/Users/xxx/Library/Application Support/Bitcoin/database ErrorFile=/Users/xxx/Library/Application Support/Bitcoin/db.log
2013-09-16 20:34:51 init message: Loading block index...
2013-09-16 20:34:51 Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/blocks/index
2013-09-16 20:34:51 Opened LevelDB successfully
2013-09-16 20:34:51 Opening LevelDB in /Users/xxx/Library/Application Support/Bitcoin/chainstate
2013-09-16 20:34:57 Opened LevelDB successfully
2013-09-16 20:35:13 LoadBlockIndexDB(): last block file = 81
2013-09-16 20:35:13 LoadBlockIndexDB(): last block file info: CBlockFileInfo(blocks=151, size=14001756, heights=257913...258060, time=2013-09-14...2013-09-15)
2013-09-16 20:35:13 LoadBlockIndexDB(): transaction index disabled
2013-09-16 20:35:13 LoadBlockIndexDB(): hashBestChain=000000000000000a74dc1374e29fa28c99fec1e4b4fdbbae7b0198983c0449d9  height=258059 date=2013-09-15 01:15:33
2013-09-16 20:35:13 init message: Verifying blocks...
2013-09-16 20:35:13 Verifying last 288 blocks at level 2
2013-09-16 20:35:31 No coin database inconsistencies in last 0 blocks (0 transactions)
2013-09-16 20:35:31  block index           40569ms
2013-09-16 20:35:31 init message: Loading wallet...
2013-09-16 20:35:55 nFileVersion = 89900
2013-09-16 20:35:55 Keys: 5131 plaintext, 0 encrypted, 2 w/ metadata, 5131 total
2013-09-16 20:35:55  wallet                24084ms
2013-09-16 20:35:55 init message: Rescanning...
2013-09-16 20:35:55 Rescanning last 11 blocks (from block 258048)...
2013-09-16 20:35:55  rescan                  246ms
2013-09-16 20:36:09 SetBestChain: new best=000000000000001935f83ff50bc4b4cd616a5605b2126406bfe5c5229dfbd862  height=258060  log2_work=71.920896  tx=23803186  date=2013-09-15 01:30:32 progress=0.983963
2013-09-16 20:36:09 init message: Loading addresses...
2013-09-16 20:36:09 Loaded 93 addresses from peers.dat  35ms
2013-09-16 20:36:09 mapBlockIndex.size() = 258071
2013-09-16 20:36:09 nBestHeight = 258060
2013-09-16 20:36:09 setKeyPool.size() = 102
2013-09-16 20:36:09 mapWallet.size() = 5928
2013-09-16 20:36:09 mapAddressBook.size() = 5036
2013-09-16 20:36:09 dnsseed thread start
2013-09-16 20:36:09 Loading addresses from DNS seeds (could take a while)
2013-09-16 20:36:09 net thread start
2013-09-16 20:36:09 addcon thread start
2013-09-16 20:36:09 opencon thread start
2013-09-16 20:36:09 msghand thread start
2013-09-16 20:36:09 dumpaddr thread start
2013-09-16 20:36:09 init message: Done loading
2013-09-16 20:36:09 trying connection 173.242.112.53:8333 lastseen=355378.8hrs
2013-09-16 20:36:09 Added 28 addresses from 178.18.90.41: 39 tried, 82 new
2013-09-16 20:36:09 Added 25 addresses from ::: 39 tried, 107 new
2013-09-16 20:36:09 trying connection 60.1.129.129:8333 lastseen=43.1hrs
2013-09-16 20:36:09 Added 24 addresses from 89.207.132.47: 39 tried, 131 new
2013-09-16 20:36:09 93 addresses found from DNS seeds
2013-09-16 20:36:09 dnsseed thread exit
2013-09-16 20:36:10 connected 60.1.129.129:8333
2013-09-16 20:36:10 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=60.1.129.129:8333, peer=60.1.129.129:8333
2013-09-16 20:36:10 trying connection 95.152.209.187:8333 lastseen=91.2hrs
2013-09-16 20:36:10 Added time data, samples 2, offset +0 (+0 minutes)
2013-09-16 20:36:10 receive version message: version 70001, blocks=258364, us=XXX.XXX.XXX.XXX:59498, them=60.1.129.129:8333, peer=60.1.129.129:8333
2013-09-16 20:36:10 connect() failed after select(): Connection refused
2013-09-16 20:36:11 trying connection 95.152.209.187:8333 lastseen=91.2hrs
2013-09-16 20:36:11 connect() failed after select(): Connection refused
2013-09-16 20:36:12 trying connection 76.10.178.108:8333 lastseen=161.1hrs
2013-09-16 20:36:12 connected 76.10.178.108:8333
2013-09-16 20:36:12 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=76.10.178.108:8333, peer=76.10.178.108:8333
2013-09-16 20:36:12 trying connection 128.4.21.210:8333 lastseen=59.7hrs
2013-09-16 20:36:12 connected 128.4.21.210:8333
2013-09-16 20:36:12 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=128.4.21.210:8333, peer=128.4.21.210:8333
2013-09-16 20:36:13 trying connection 122.228.207.153:8333 lastseen=73.4hrs
2013-09-16 20:36:13 connected 122.228.207.153:8333
2013-09-16 20:36:13 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=122.228.207.153:8333, peer=122.228.207.153:8333
2013-09-16 20:36:14 trying connection 109.228.154.37:8333 lastseen=97.7hrs
2013-09-16 20:36:14 connected 109.228.154.37:8333
2013-09-16 20:36:14 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=109.228.154.37:8333, peer=109.228.154.37:8333
2013-09-16 20:36:14 connection timeout
2013-09-16 20:36:14 trying connection 81.166.147.68:8333 lastseen=43.1hrs
2013-09-16 20:36:14 trying connection 108.162.205.54:8333 lastseen=355378.8hrs
2013-09-16 20:36:14 connected 81.166.147.68:8333
2013-09-16 20:36:14 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=81.166.147.68:8333, peer=81.166.147.68:8333
2013-09-16 20:36:15 trying connection 2.229.10.127:8333 lastseen=153.1hrs
2013-09-16 20:36:15 connected 2.229.10.127:8333
2013-09-16 20:36:15 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=2.229.10.127:8333, peer=2.229.10.127:8333
2013-09-16 20:36:19 connection timeout
2013-09-16 20:36:20 trying connection 67.14.164.114:8333 lastseen=355378.8hrs
2013-09-16 20:36:20 connected 67.14.164.114:8333
2013-09-16 20:36:20 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=67.14.164.114:8333, peer=67.14.164.114:8333
2013-09-16 20:37:15 socket no message in first 60 seconds, 0 1
2013-09-16 20:37:15 disconnecting node 81.166.147.68:8333
2013-09-16 20:37:15 trying connection 203.219.208.58:8333 lastseen=81.6hrs
2013-09-16 20:37:15 connected 203.219.208.58:8333
2013-09-16 20:37:15 send version message: version 70001, blocks=258060, us=0.0.0.0:0, them=203.219.208.58:8333, peer=203.219.208.58:8333
2013-09-16 20:45:49 ThreadRPCServer method=listtransactions
2013-09-16 20:48:14 ThreadRPCServer method=listtransactions
2013-09-16 20:51:09 Flushed 170 addresses to peers.dat  151ms
2013-09-16 21:06:09 Flushed 170 addresses to peers.dat  143ms
2013-09-16 21:08:58 ThreadRPCServer method=stop
2013-09-16 21:08:58 addcon thread interrupt
2013-09-16 21:08:58 dumpaddr thread stop
2013-09-16 21:08:58 net thread interrupt
2013-09-16 21:08:58 opencon thread interrupt
2013-09-16 21:21:35 ThreadRPCServer method=stop

gmaxwell commented at 9:48 PM on September 16, 2013: contributor

Reporting bugs on month old git snapshots is not very helpful. Can you tell us if it works on either v0.8.5 or current git?

Rescan should not have the effect you've described. It doesn't have any influence on the blockchain handling.

ghost commented at 9:57 PM on September 16, 2013: none

You didn't read far enough into my description, "I have also kept updating to git head after every version to see if the problem resolves".

Rescan should not have the effect you've described. It doesn't have any influence on the blockchain handling.

And yet it does. Maybe it threading or locking issue. This bug is 100% reproducible for me at this point.

gmaxwell commented at 10:05 PM on September 16, 2013: contributor

Can you remove your checklevel=2 setting and see if you get any errors?

ghost commented at 10:24 PM on September 16, 2013: none

No errors:

2013-09-16 22:12:20 init message: Verifying blocks...
2013-09-16 22:12:20 Verifying last 288 blocks at level 3
2013-09-16 22:21:42 No coin database inconsistencies in last 247 blocks (49357 transactions)
2013-09-16 22:21:43  block index          581930ms

gavinandresen commented at 11:24 PM on September 16, 2013: contributor

Just a data point: I'm also running OSX 10.7.5, and have never seen a hang-on-startup.

What version of Boost are you compiling against? This sounds a little like the hang-at-shutdown problem that was caused by a bug in some versions of boost::microsleep.

ghost commented at 11:32 PM on September 16, 2013: none

> port installed | grep boost
boost [@1](/bitcoin-bitcoin/contributor/1/).54.0_0+no_single+no_static+python27 (active)

gavinandresen commented at 1:43 AM on September 17, 2013: contributor

Not boost (I'm running exactly the same version).

Does it hang if you run -testnet or on an empty -datadir ?

ghost commented at 2:12 AM on September 17, 2013: none

No, -testnet on an empty -datadir works fine. I also stopped and restarted it several times and it worked ok.

ghost commented at 10:41 PM on October 29, 2013: none

I tried latest git HEAD again and it no longer hangs for me on startup. Never did figure out in which version this problem started, but I did notice something strange in the logs. I had a few old transactions that had never been accepted because I didn't add a fee, but bitcoind was still trying to resend them, even after several months. Not sure if that's related, but the message about the inputs already being spent appears in the log right before the peer messages and the hang.

unknown closed this on Oct 29, 2013

Bushstar referenced this in commit 5809c5c3d0 on Apr 8, 2020

Bushstar referenced this in commit 99824a8792 on Apr 8, 2020

DrahtBot locked this on Sep 8, 2021