bitcoind AND bitcoinj as full node fails on block download, any suggestions why?

[Bitdev181]

TL/DR:
bitcoinj disconnects from bitcoind in regtest mode when bitcoinj is in fullpruned mode right after bitcoind serves a block. logs below. timing mishap in log seems to be an issue.


Hello again. im curious if anybody here that understands bitcoin better than myself can take a look at these logs and maby identify what is going on. why, when i try to download the blockchain with a fullprunedblockchain (everything else works, any store, spvchain,etc..) does bitcoinj force disconnect right after bitcoind serves the full block?
I hope somebody here can help me, im like 3 weeks in on the same issue with no progress even with a few sets of eyes on it, and documentation on regtest with bitcoinj in full node mode is lacking/non existant (or i just cant find it). i can not get the bitcoinj library working with a fullprunedblockchain in a regtest environment (testnet + mainnet work fine).


i along with a few others built a full wallet from scratch using only the lower level classes in spvblockstore mode, but it failed during the change to full pruned so i set that aside for now and started testing with a custom version of the walletappkit class and also re-writing a fresh class that is as simple as can be. i literally just began using that class, changed the chain + store, and started debugging the kit to take the variable out of incorrect code being the issue (however the FPBC may require something additional i dont know about). the few paragraphs of info i found on fullprunedblockstore state it should be handled about the same as anything else in terms of how to connect and DL the chain.

 im curious if anybody can spot why im having this issue. i believe the code is correct but i may be mistaken, if it was code it would be solved by now. i even tried with no verification scripts, whitelisting, whitebinding,multiple local nodes in round robin in an attempt to help with verification to no avail. but i think it is my bitcoin node in -regtest mode. running no special flags other than -server and -listen and -regtest and -bind to 127.0.0.1 (well recently ive added quite a bit more, no changes)



here is the recent bitcoinj log. the final null pointer exception and illegal state exception repeat on each peer reconnect, alsop triggering peerDisconnectedEventListener and occasionally a peerConnect EV every 30 or so disconnects. bitcoind is clearing node state on each disconnect and adding a new peer every time the disconnect message shows. it works with testnet3params just fine and dns peer discovery but i cant use testnet now.

the wallet/chain height mismatch is strange to me.

the timing mishap is biggest red flag, not sure what it means or how to resolve, even local nodes have timing mishaps when running multiple bitcoind nodes.

bitcoind version 12,14,and 15 were tried.

 

the bitcoind getpeerinfo on bitcoinj peer when bitcoinj is just grabbing a single block header, pulling during block sync is too hard since its disconnecting too often.

Code:

 {
    "id": 45, (this is because node has been running through failed sync disconnecting 44 prior peers)
    "addr": "127.0.0.1:19094",
    "addrlocal": "127.0.0.1:18444",
    "addrbind": "127.0.0.1:18444",
    "services": "0000000000000000",
    "relaytxes": true,
    "lastsend": 1507401729,
    "lastrecv": 1507401729,
    "bytessent": 722,
    "bytesrecv": 340,
    "conntime": 1507401723,
    "timeoffset": 0,
    "version": 70001,
    "subver": "/bitcoinj:0.14.5/",
    "inbound": true,
    "addnode": false,
    "startingheight": 0,
    "banscore": 0,
    "synced_headers": -1,
    "synced_blocks": -1,
    "inflight": [
    ],
    "whitelisted": true,
    "bytessent_per_msg": {
      "alert": 192,
      "block": 250,
      "ping": 32,
      "pong": 96,
      "verack": 24,
      "version": 128
    },
    "bytesrecv_per_msg": {
      "getdata": 61,
      "ping": 96,
      "pong": 32,
      "verack": 24,
      "version": 127
    }
  }

Bitcoind Log: (had to edit some things with "x"s, sorry for this)

Code:

    2017-10-01 07:47:33 receive version message: /bitcoinj:0.14.5/: version 70001, blocks=0, us=127.0.0.1:18444, peer=75
    2017-10-01 07:47:33 sending alert (168 bytes) peer=75
    2017-10-01 07:47:33 received: verack (0 bytes) peer=75
    2017-10-01 07:47:33 sending ping (8 bytes) peer=75
    2017-10-01 07:47:33 received: getblocks (69 bytes) peer=75
    2017-10-01 07:47:33 getblocks 1 to end limit 500 from peer=75
    2017-10-01 07:47:33 sending inv (3637 bytes) peer=75
    2017-10-01 07:47:33 received: pong (8 bytes) peer=75
    2017-10-01 07:47:33 pong peer=75: Timing mishap, f53e1xxxxxx71798 expected, f53e1xxxxxx71798 received, 8 bytes
    2017-10-01 07:47:33 received: getdata (3637 bytes) peer=75
    2017-10-01 07:47:33 received getdata (101 invsz) peer=75
    2017-10-01 07:47:33 received getdata for: block 0f09eb8064aa08a45fa5f49097b150875ac752944xxxxxxxxxxxxxxxxxxxx peer=75
    2017-10-01 07:47:33 sending block (226 bytes) peer=75
    2017-10-01 07:47:33 sending block (226 bytes) peer=75
    2017-10-01 07:47:33 socket closed
    2017-10-01 07:47:33 sending block (226 bytes) peer=75
    2017-10-01 07:47:33 disconnecting peer=75
    2017-10-01 07:47:35 Added connection peer=76

The bitcoinj log:

Code:

    [main] INFO org.bitcoinj.core.Context - Creating bitcoinj 0.14.5 context.
    [CUSTOMKIT STARTING] INFO CUSTOMKIT - Starting up with directory = test10021711.wallet (not saving or loading wallets, this is not applicable)
    [CUSTOMKIT STARTING] INFO org.bitcoinj.wallet.DeterministicKeyChain - 133 keys needed for M/0H/0 = 1 issued + 100 lookahead size + 33 lookahead threshold - 1 num children
    [CUSTOMKIT STARTING] INFO org.bitcoinj.wallet.DeterministicKeyChain - Took 54.86 ms
    [CUSTOMKIT STARTING] INFO org.bitcoinj.wallet.DeterministicKeyChain - 133 keys needed for M/0H/1 = 0 issued + 100 lookahead size + 33 lookahead threshold - 0 num children
    [CUSTOMKIT STARTING] INFO org.bitcoinj.wallet.DeterministicKeyChain - Took 24.25 ms
    [CUSTOMKIT STARTING] INFO org.bitcoinj.core.AbstractBlockChain - chain head is at height 0:
     block: 
       hash: 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206
       version: 1
       previous block: 0000000000000000000000000000000000000000000000000000000000000000
       merkle root: 4a5e1e4baab89f3a32518a88c31bc87f618f76673e2cc77ab2127b7afdeda33b
       time: 1296688602 (2011-02-02T23:16:42Z)
       difficulty target (nBits): 545259519
       nonce: 2
    
    [CUSTOMKIT STARTING] WARN org.bitcoinj.core.AbstractBlockChain - Wallet/chain height mismatch: -1 vs 0
    [CUSTOMKIT STARTING] WARN org.bitcoinj.core.AbstractBlockChain - Hashes: null vs 0f9188f13cb7b2cxxxxxxxxx3a4fc328bf5beb436012afca590b1a11466e2206
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Starting ...
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Localhost peer detected, trying to use it instead of P2P discovery
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 0 max)
    [NioClientManager] INFO org.bitcoinj.net.NioClientManager - Connected to /127.0.0.1:18444
    [NioClientManager] INFO org.bitcoinj.core.Peer - Announcing to /127.0.0.1:18444 as: /bitcoinj:0.14.5/
    [NioClientManager] INFO org.bitcoinj.core.Peer - [127.0.0.1]:18444: Got version=70015, subVer='/Satoshi:0.14.2/', services=0x13, time=2017-10-01 03:47:27, blocks=101
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - [127.0.0.1]:18444: New peer      (1 connected, 0 pending, 1 max)
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - Setting download peer: [127.0.0.1]:18444
    [NioClientManager] INFO org.bitcoinj.core.listeners.DownloadProgressTracker - Downloading block chain of size 101. 
    [NioClientManager] INFO org.bitcoin.Secp256k1Context - java.lang.UnsatisfiedLinkError: no secp256k1 in java.library.path
    [NioClientManager] WARN org.bitcoinj.core.PeerSocketHandler - [127.0.0.1]:18444 - 
    java.lang.NullPointerException
    	at org.bitcoinj.core.NetworkParameters.getTransactionVerificationFlags(NetworkParameters.java:517)
    	at org.bitcoinj.core.FullPrunedBlockChain.connectTransactions(FullPrunedBlockChain.java:234)
    	at org.bitcoinj.core.AbstractBlockChain.connectBlock(AbstractBlockChain.java:561)
    	at org.bitcoinj.core.AbstractBlockChain.add(AbstractBlockChain.java:489)
    	at org.bitcoinj.core.AbstractBlockChain.add(AbstractBlockChain.java:352)
    	at org.bitcoinj.core.Peer.processBlock(Peer.java:996)
    	at org.bitcoinj.core.Peer.processMessage(Peer.java:491)
    	at org.bitcoinj.core.PeerSocketHandler.receiveBytes(PeerSocketHandler.java:182)
    	at org.bitcoinj.net.ConnectionHandler.handleKey(ConnectionHandler.java:223)
    	at org.bitcoinj.net.NioClientManager.handleKey(NioClientManager.java:86)
    	at org.bitcoinj.net.NioClientManager.run(NioClientManager.java:122)
    	at com.google.common.util.concurrent.AbstractExecutionThreadService$1$2.run(AbstractExecutionThreadService.java:60)
    	at com.google.common.util.concurrent.Callables$3.run(Callables.java:95)
    	at org.bitcoinj.utils.ContextPropagatingThreadFactory$1.run(ContextPropagatingThreadFactory.java:49)
    	at java.lang.Thread.run(Unknown Source)
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - [127.0.0.1]:18444: Peer died      (0 connected, 0 pending, 1 max)
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - Download peer died. Picking a new one.
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - Unsetting download peer: [127.0.0.1]:18444
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Peer discovery took 19.33 ?s and returned 0 items
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Waiting 1500 msec before next connect attempt to [127.0.0.1]:18444
    [NioClientManager] WARN org.bitcoinj.net.ConnectionHandler - Error handling SelectionKey: java.lang.IllegalStateException 
    java.lang.IllegalStateException
    	at com.google.common.base.Preconditions.checkState(Preconditions.java:158)
    	at org.bitcoinj.net.ConnectionHandler.handleKey(ConnectionHandler.java:224)
    	at org.bitcoinj.net.NioClientManager.handleKey(NioClientManager.java:86)
    	at org.bitcoinj.net.NioClientManager.run(NioClientManager.java:122)
    	at com.google.common.util.concurrent.AbstractExecutionThreadService$1$2.run(AbstractExecutionThreadService.java:60)
    	at com.google.common.util.concurrent.Callables$3.run(Callables.java:95)
    	at org.bitcoinj.utils.ContextPropagatingThreadFactory$1.run(ContextPropagatingThreadFactory.java:49)
    	at java.lang.Thread.run(Unknown Source)
    [PeerGroup Thread] INFO org.bitcoinj.core.PeerGroup - Attempting connection to [127.0.0.1]:18444     (0 connected, 1 pending, 1 max)
    [NioClientManager] INFO org.bitcoinj.net.NioClientManager - Connected to /127.0.0.1:18444
    [NioClientManager] INFO org.bitcoinj.core.Peer - Announcing to /127.0.0.1:18444 as: /bitcoinj:0.14.5/
    [NioClientManager] INFO org.bitcoinj.core.Peer - [127.0.0.1]:18444: Got version=70015, subVer='/Satoshi:0.14.2/', services=0x13, time=2017-10-01 03:47:29, blocks=101
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - [127.0.0.1]:18444: New peer      (1 connected, 0 pending, 1 max)
    [NioClientManager] INFO org.bitcoinj.core.PeerGroup - Setting download peer: [127.0.0.1]:18444
    [NioClientManager] INFO org.bitcoinj.core.listeners.DownloadProgressTracker - Chain download switched to [127.0.0.1]:18444

(this is the first null pointer error) line 517 of org.bitcoinj.core.NetworkParameters:
    

Code:

      if (block.getVersion() >= Block.BLOCK_VERSION_BIP65 &&
                tally.getCountAtOrAbove(Block.BLOCK_VERSION_BIP65) > this.getMajorityEnforceBlockUpgrade()) {
                verifyFlags.add(Script.VerifyFlag.CHECKLOCKTIMEVERIFY);
            }

[achow101]

Can you please post your code for setting up the block store?

It looks like the problem is that tally is null which implies that the implementation of fullprunedblockstore is incorrect.

I am certain that the problem you are experiencing has nothing to do with bitcoind or any settings. Rather I'm fairly certain that this problem is because it is throwing an exception when trying to validate a block which is causing the networking portion to crash and thus disconnect.

[Bitdev181]

update:

So it seems to me bitcoinj could be bugged? well kind of. it may be intended functionality. my block version is high because of the transaction verification rules, but a chain is expected to have a block version 1 at the genesis block, so this strange version is really throwing off bitcoinj i think. mainnet works, testnet works, regtest does not primarily because bitcoinj was programmed to handle the forks when verifying the transactions, and it knows mainnet will always have a version of 1 at its genesis block and for awhile thereafter. and when the code was made it expects something in the block-chain. and the people who made bitcoinj never thought to add an  if tally != Null. but maybe checklocktimeverify should be ran on the first blocks anyway? i dont know.

i think the only fix is to update bitcoinj and re-compile it which i will do however i don't want to compromise security by doing this, and im not sure how it will effect me when i move back to mainnet.

[Bitdev181]

found my solution, added a check if tally is null in the NEtworkParameters.java file and re-compiled the jar. seems liek a workaround but really i think its fine as in mainnet it will work as expected and it allows regtest to work and checkLockTime will still be set down the line on the chain.