indexd is running but not indexing new blocks

unsystemizer commented 6 years ago

a) Install and start bitcoind and indexd for the first time (both were syncing from scratch) b) Last night SSH sessions to these systems dropped because notebook went to sleep mode. bitocoind was running in the background, so it didn't get interrupted. c) This morning I connected again and started indexd (yesterday it was running in foreground so it stopped when SSH connection dropped). As shown above, indexd API is now working and showing the current, correct chainBlock, but blocksBehind is increasing (i.e. indexing is not working, blockIndex is stuck at 1211212)

root@indexd:/data/indexd/indexd-testnet# curl http://localhost:18432/status
{"chainBlock":1211215,"indexBlock":1211212,"blocksBehind":3,"ready":false}

indexd LOG file:

# tail -f LOG
2017/10/28-05:54:54.264780 7f6eb9cca700 Recovering log #15703
2017/10/28-05:55:11.497125 7f6eb9cca700 Level-0 table #15714: started
2017/10/28-05:55:16.870921 7f6eb9cca700 Level-0 table #15714: 475144539 bytes OK
2017/10/28-05:55:16.908894 7f6eb9cca700 Delete type=3 #9
2017/10/28-05:55:16.909430 7f6eb9cca700 Delete type=0 #15703

Bitcoin daemon status:

root@indexd:/data/indexd/indexd-testnet# bitcoin-cli getblockchaininfo
{
  "chain": "test",
  "blocks": 1211215,
  "headers": 1211215,
  "bestblockhash": "000000001eb9ec8f83980220f52bff577c06a0798ea77a6a2133cb2f1f212322",
  "difficulty": 1,
  "mediantime": 1509166914,
  "verificationprogress": 0.9999985607027567,
  "chainwork": "0000000000000000000000000000000000000000000000318e74502323fed131",
  "pruned": false,
  "softforks": [
    {
      "id": "bip34",
      "version": 2,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip66",
      "version": 3,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip65",
      "version": 4,
      "reject": {
        "status": true
      }
    }
  ],
  "bip9_softforks": {
    "csv": {
      "status": "active",
      "startTime": 1456790400,
      "timeout": 1493596800,
      "since": 770112
    },
    "segwit": {
      "status": "active",
      "startTime": 1462060800,
      "timeout": 1493596800,
      "since": 834624
    }
  }
}

I checked to make sure that I have just one indexd running.

# ps -ef | grep index
root      8930  8920  0 05:54 ?        00:00:00 node /usr/bin/forever index.js
root      8940  8930  0 05:54 ?        00:00:24 /usr/bin/node /indexd/index.js
root      9244  8901  0 07:18 ?        00:00:00 grep --color=auto index

Is this normal?

I stopped and started indexd and it caught up. I'll now leave it running in foreground and hopefully duplicate this problem.

root@indexd:/indexd# nodejs --version
v6.11.5
root@indexd:/indexd# npm --version
3.10.10

deweller commented 6 years ago

This is based on the counterparty indexd server at: https://github.com/CounterpartyXCP/indexd-server

But the index service is almost a direct copy and paste of: https://github.com/bitcoinjs/indexd/blob/master/example/service.js

dcousens commented 6 years ago

As shown above, indexd API is now working and showing the current, correct chainBlock, but blocksBehind is increasing (i.e. indexing is not working, blockIndex is stuck at 1211212)

This doesn't make sense. Either indexd has an old tip, or it doesn't, which do you mean here? The quote implies that the tip hash was valid, but height wasn't?

unsystemizer commented 6 years ago

I mean chainBlock and blocksBehind keep going up, and indexBlock is stuck.

$ curl http://localhost:18432/status
{"chainBlock":1211215,"indexBlock":1211212,"blocksBehind":3,"ready":false}

Wait 10 min - chainBlock is up by 1, blocksBehind as well, i.e. service is running, but indexBlock is stuck.

$ curl http://localhost:18432/status
{"chainBlock":1211216,"indexBlock":1211212,"blocksBehind":4,"ready":false}

What debug output should I gather if I see this again?

dcousens commented 6 years ago

I think a dump of your debug output would great. Do you have DEBUG=blockchain enabled?

ps: we should probably make that DEBUG=indexd:blockchain

unsystemizer commented 6 years ago

I didn't have that. I'll set DEBUG=blockchain now and report back if I encounter this again

DEBUG=indexd:blockchain

Yes it'd be nice to know what categories are available and to be able to tell by service name.

unsystemizer commented 6 years ago

This time SSH terminal disconnects didn't work, so I tried different things... I started bitcoind with -reindex, then after it reparsed all the blocks, I started indexd-server (indexd packaged by Counterparty) with DEBUG enabled on both ends.

blocksBehind increasing:

root@indexd:~# curl http://localhost:18432/status
{"chainBlock":1211388,"indexBlock":1211386,"blocksBehind":2,"ready":false}
root@indexd:~# curl http://localhost:18432/status
{"chainBlock":1211389,"indexBlock":1211386,"blocksBehind":3,"ready":false}

indexd knows it's behind, but it's not updating.

(I think zmq lost messages may be because bitcind is busy reindexing or the high setting of index (32) is higher than rpcworkqueue (16), which I mentioned in the other issue)

Mon, 30 Oct 2017 16:05:11 GMT resync fetching bitcoind/local tips
Mon, 30 Oct 2017 16:05:11 GMT mempool 7a3ec812adee2972e09b2a3c9b0d92c2f7ff24716f89b7cd778e1d9e90352ecd dropped
Mon, 30 Oct 2017 16:05:11 GMT mempool fbe64eba2036bafdc0436a7570d01822380b536d4fe66dca34a4c4a62f59a446 dropped
Mon, 30 Oct 2017 16:05:11 GMT mempool 6e212a0147f03eb0f36a7fefa94ffbe557eb0f537a0bc5316c0c6861fc2be7c2 dropped
Mon, 30 Oct 2017 16:05:11 GMT resync ... { local: '00000000909f82fbf72cd70baca712e2ed15a1d1e735d3dbab691c81fde7f19a',
  bitcoind: '0000000000000013ad75dc885d2d96e124c1e0c6a88754eeeecb166cba1503d0' }
Mon, 30 Oct 2017 16:05:11 GMT resync bitcoind is ahead
Mon, 30 Oct 2017 16:05:11 GMT resync Connecting 00000000000085aa07bbf789d83f11474ff6667db442e0fcfcb7f89d19b9352c @ 1211387
2017-10-30T16:05:11.421Z service Error: JSON value is not a boolean as expected
    at batch.forEach (/indexd/node_modules/yajrpc/index.js:69:34)
    at Array.forEach (native)
    at dhttp (/indexd/node_modules/yajrpc/index.js:61:11)
    at done (/indexd/node_modules/dhttp/index.js:17:19)
    at handle (/indexd/node_modules/dhttp/index.js:61:7)
    at /indexd/node_modules/dhttp/parsers.js:30:7
    at /indexd/node_modules/dhttp/parsers.js:21:5
    at IncomingMessage.<anonymous> (/indexd/node_modules/dhttp/parsers.js:13:5)
    at emitNone (events.js:91:20)
    at IncomingMessage.emit (events.js:185:7)
Mon, 30 Oct 2017 16:05:11 GMT express:router dispatching GET /status
Mon, 30 Oct 2017 16:05:11 GMT express:router query  : /status
Mon, 30 Oct 2017 16:05:11 GMT express:router expressInit  : /status
Mon, 30 Oct 2017 16:05:11 GMT express:router router  : /status
Mon, 30 Oct 2017 16:05:11 GMT express:router dispatching GET /status
2017-10-30T16:05:14.684Z zmq 15770587 messages lost
Mon, 30 Oct 2017 16:05:14 GMT resync fetching bitcoind/local tips
Mon, 30 Oct 2017 16:05:14 GMT resync ... { local: '00000000909f82fbf72cd70baca712e2ed15a1d1e735d3dbab691c81fde7f19a',
  bitcoind: '0000000000000013ad75dc885d2d96e124c1e0c6a88754eeeecb166cba1503d0' }
Mon, 30 Oct 2017 16:05:14 GMT resync bitcoind is ahead
Mon, 30 Oct 2017 16:05:14 GMT resync Connecting 00000000000085aa07bbf789d83f11474ff6667db442e0fcfcb7f89d19b9352c @ 1211387
2017-10-30T16:05:14.687Z service Error: JSON value is not a boolean as expected
    at batch.forEach (/indexd/node_modules/yajrpc/index.js:69:34)
    at Array.forEach (native)
    at dhttp (/indexd/node_modules/yajrpc/index.js:61:11)
    at done (/indexd/node_modules/dhttp/index.js:17:19)
    at handle (/indexd/node_modules/dhttp/index.js:61:7)
    at /indexd/node_modules/dhttp/parsers.js:30:7
    at /indexd/node_modules/dhttp/parsers.js:21:5
    at IncomingMessage.<anonymous> (/indexd/node_modules/dhttp/parsers.js:13:5)
    at emitNone (events.js:91:20)
    at IncomingMessage.emit (events.js:185:7)
2017-10-30T16:05:18.948Z zmq:tx hashtx afd8a8508b3c7811ec43ae8af658011d2c93a884dfd441314ca477fb4686d3d4
2017-10-30T16:05:18.948Z zmq:tx hashtx d0c43e68c750685b7ae4f0ed56de4b36a8c99bcf97dbfa790e0bc5a27fba873b
2017-10-30T16:05:21.790Z zmq:tx hashtx 7b499b275111898d414d478d74aa689d89154dd2966596125f0adf9429d71aac
2017-10-30T16:05:21.909Z zmq:tx hashtx 27e1c795a9d499300b06c560e9e06175cd3032c6874e85fcf143d21f7345de83

bitcoind:

root@indexd:~# bitcoin-cli getblockchaininfo
{
  "chain": "test",
  "blocks": 1211389,
  "headers": 1211389,
  "bestblockhash": "0000000000000013ad75dc885d2d96e124c1e0c6a88754eeeecb166cba1503d0",
  "difficulty": 37063081.71310107,
  "mediantime": 1509374741,
  "verificationprogress": 0.9999988776422514,
  "chainwork": "0000000000000000000000000000000000000000000000319bb59806b335212f",
  "pruned": false,
  "softforks": [
    {
      "id": "bip34",
      "version": 2,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip66",
      "version": 3,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip65",
      "version": 4,
      "reject": {
        "status": true
      }
    }
  ],
  "bip9_softforks": {
    "csv": {
      "status": "active",
      "startTime": 1456790400,
      "timeout": 1493596800,
      "since": 770112
    },
    "segwit": {
      "status": "active",
      "startTime": 1462060800,
      "timeout": 1493596800,
      "since": 834624
    }
  }
}

Then I waited until the next block...

bitcoind:

root@indexd:~# bitcoin-cli getblockchaininfo
{
  "chain": "test",
  "blocks": 1211390,
  "headers": 1211390,
  "bestblockhash": "00000000c48fff7f47369d0c9336bb91ef362b23143996b5c4da3b38644ae540",
  "difficulty": 1,
  "mediantime": 1509375610,
  "verificationprogress": 0.9999990678767521,
  "chainwork": "0000000000000000000000000000000000000000000000319bb59807b3362130",
  "pruned": false,
  "softforks": [
    {
      "id": "bip34",
      "version": 2,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip66",
      "version": 3,
      "reject": {
        "status": true
      }
    },
    {
      "id": "bip65",
      "version": 4,
      "reject": {
        "status": true
      }
    }
  ],
  "bip9_softforks": {
    "csv": {
      "status": "active",
      "startTime": 1456790400,
      "timeout": 1493596800,
      "since": 770112
    },
    "segwit": {
      "status": "active",
      "startTime": 1462060800,
      "timeout": 1493596800,
      "since": 834624
    }
  }
}

indexd:

2017-10-30T16:25:21.198Z zmq:tx hashtx 42d40a1c1d62fed18a2e75c2d1bde4dabc6c883882d9f7664798dc0251309955
2017-10-30T16:25:21.198Z zmq -15770803 messages lost
Mon, 30 Oct 2017 16:25:21 GMT resync fetching bitcoind/local tips
Mon, 30 Oct 2017 16:25:21 GMT mempool 3edb1d993cbb5128744f3e628ee8ff8df65455855ad227e0490a8ba8a9048bd7 dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 390606887194fcf15222e5e9aaeb35506ce668d9a7fc5c3be5eb9d2e9661adca dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 1946304f2e81690c9c1eca8bbfed80920a16428dc75d40e513ba8543a056c6ea dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 291e38de3bf38aeb7688a5301e293fb3b2183648d3a5096cef7d3ede4a5f2fd4 dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 8f700f60eb5c2550619229dff777ac5a4cd39dc08918ce41bff6d7e33201d442 dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool a58a92129744664c816020872b1bcdafc852b416d7a022f6b112f23b6402555c dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 1e3bb2f677fd99fe46d5511232e6a7e336797873ac903f9b1518d6a3489153dd dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 52b83f3fed3ff49930da8d9294b4c9924e368271d261b4d2fbd0a6ef5c3eac8c dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool 3a95c8584f620597ef791760d0a405c1f03a3f8bc8d8221894f1a78d983c1f4c dropped
Mon, 30 Oct 2017 16:25:21 GMT mempool cdc51a8334b7b9917c0c1ba1877f8714912a1c5992028616ed31fa404c997a2b dropped
Mon, 30 Oct 2017 16:25:21 GMT resync ... { local: '00000000909f82fbf72cd70baca712e2ed15a1d1e735d3dbab691c81fde7f19a',
  bitcoind: '00000000c48fff7f47369d0c9336bb91ef362b23143996b5c4da3b38644ae540' }
Mon, 30 Oct 2017 16:25:21 GMT resync bitcoind is ahead
Mon, 30 Oct 2017 16:25:21 GMT resync Connecting 00000000000085aa07bbf789d83f11474ff6667db442e0fcfcb7f89d19b9352c @ 1211387
2017-10-30T16:25:21.232Z service Error: JSON value is not a boolean as expected
    at batch.forEach (/indexd/node_modules/yajrpc/index.js:69:34)
    at Array.forEach (native)
    at dhttp (/indexd/node_modules/yajrpc/index.js:61:11)
    at done (/indexd/node_modules/dhttp/index.js:17:19)
    at handle (/indexd/node_modules/dhttp/index.js:61:7)
    at /indexd/node_modules/dhttp/parsers.js:30:7
    at /indexd/node_modules/dhttp/parsers.js:21:5
    at IncomingMessage.<anonymous> (/indexd/node_modules/dhttp/parsers.js:13:5)
    at emitNone (events.js:91:20)
    at IncomingMessage.emit (events.js:185:7)
2017-10-30T16:25:25.222Z zmq 15770802 messages lost
Mon, 30 Oct 2017 16:25:25 GMT resync fetching bitcoind/local tips
Mon, 30 Oct 2017 16:25:25 GMT resync ... { local: '00000000909f82fbf72cd70baca712e2ed15a1d1e735d3dbab691c81fde7f19a',
  bitcoind: '00000000c48fff7f47369d0c9336bb91ef362b23143996b5c4da3b38644ae540' }
Mon, 30 Oct 2017 16:25:25 GMT resync bitcoind is ahead
Mon, 30 Oct 2017 16:25:25 GMT resync Connecting 00000000000085aa07bbf789d83f11474ff6667db442e0fcfcb7f89d19b9352c @ 1211387
2017-10-30T16:25:25.227Z service Error: JSON value is not a boolean as expected
    at batch.forEach (/indexd/node_modules/yajrpc/index.js:69:34)
    at Array.forEach (native)
    at dhttp (/indexd/node_modules/yajrpc/index.js:61:11)
    at done (/indexd/node_modules/dhttp/index.js:17:19)
    at handle (/indexd/node_modules/dhttp/index.js:61:7)
    at /indexd/node_modules/dhttp/parsers.js:30:7
    at /indexd/node_modules/dhttp/parsers.js:21:5
    at IncomingMessage.<anonymous> (/indexd/node_modules/dhttp/parsers.js:13:5)
    at emitNone (events.js:91:20)
    at IncomingMessage.emit (events.js:185:7)
2017-10-30T16:25:29.305Z zmq:tx hashtx 9304a0fd0d832f6b637b9fd4cda09cb09aa3232ed0892161789a8f67305c49d8
2017-10-30T16:25:29.307Z zmq:tx hashtx fde3499809ea8803a6b078e12e7ff54d198b79ea3588a364c9f2348c337ac174

I captured verbose bitcoind.log of this time interval and posted it here:

https://gist.github.com/unsystemizer/b8e9b67331e583b23125d77990da0adb

After this I stopped indexd but when I restart it, it remains stuck. Let me know if you need any DB files or anything else.

2017-10-30T16:32:49.477Z index App listening on port 18432
Mon, 30 Oct 2017 16:32:49 GMT resync ... { local: '00000000909f82fbf72cd70baca712e2ed15a1d1e735d3dbab691c81fde7f19a',
  bitcoind: '00000000c48fff7f47369d0c9336bb91ef362b23143996b5c4da3b38644ae540' }
Mon, 30 Oct 2017 16:32:49 GMT resync bitcoind is ahead
Mon, 30 Oct 2017 16:32:49 GMT resync Connecting 00000000000085aa07bbf789d83f11474ff6667db442e0fcfcb7f89d19b9352c @ 1211387
2017-10-30T16:32:49.492Z service Error: JSON value is not a boolean as expected
    at batch.forEach (/indexd/node_modules/yajrpc/index.js:69:34)
    at Array.forEach (native)
    at dhttp (/indexd/node_modules/yajrpc/index.js:61:11)
    at done (/indexd/node_modules/dhttp/index.js:17:19)
    at handle (/indexd/node_modules/dhttp/index.js:61:7)
    at /indexd/node_modules/dhttp/parsers.js:30:7
    at /indexd/node_modules/dhttp/parsers.js:21:5
    at IncomingMessage.<anonymous> (/indexd/node_modules/dhttp/parsers.js:13:5)
    at emitNone (events.js:91:20)
    at IncomingMessage.emit (events.js:185:7)
Mon, 30 Oct 2017 16:32:53 GMT express:router dispatching GET /status

deweller commented 6 years ago

Yeah - the key here is the JSON value is not a boolean as expected error. If we could figure out which RPC call is returning this error, then I think that would solve this issue.

It would be helpful for indexd to log which rpc method failed in this type of situation.

unsystemizer commented 6 years ago

@deweller pointed out he had the same problem with pre-0.15 bitcoind. I checked mine, I built it myself and it had version 149900 - might have been 0.15 RC2 or something... I just installed 0.15.0.1 and will confirm if I duplicate this issue

It would be helpful for indexd to log which rpc method failed in this type of situation.

That's what I was worried about.

It might be getblock from https://gist.github.com/unsystemizer/b8e9b67331e583b23125d77990da0adb#file-debug-log-L278, but sending inv (145 bytes) peer=4 clearly doesn't help... If I manage to duplicate this again I'll capture tcpdump logs as well...

Because time granularity isn't sufficient to be sure (there's getblockheader in L276, identical log time), next time I should also add -logtimemicros to bitcoind options. (I wonder if the same precision is available in NodeJS and how we can enable it? It's not strictly necessary here - if I have tcpdump I may not need this, but if tcpdump isn't possible...)

dcousens commented 6 years ago

Namespaced debug and made it optional in 0a07d06

dcousens commented 6 years ago

@deweller 336be99 should help in tracing these calls... it can otherwise be difficult due to the async nature.

The error thrown still sucks, but, if you enable debug=indexd:rpc, you'll see where it fails. I personally use debug=* for these cases, so, that should hlep.

unsystemizer commented 6 years ago

Thanks. I was using debug=* in my debugging, by the way. It seems just records the calls and not the names of methods used.

dcousens commented 6 years ago

Cannot reproduce with latest, published v0.7.6 (master), please try! If you can reproduce, re-open.

bitcoinjs / indexd

indexd is running but not indexing new blocks #20