Bitcoind timing mishap?

[Bitdev181]

So i recently posted a large question here that involves both bitcoind and j.


https://bitcointalk.org/index.php?topic=2245534.msg22688171#msg22688171

this talks about what bitcoinj is doing but half the question related to bitcoind exclusively. so i have a few questions i will list here without the bitcoinj stuff and split the one question in to 2 sets of questions basically. if this is not allowed please just delete this topic and i wont re-post.


bitcoind is disconnecting my bitcoin j node (i think) after the block is served. bitcoinj says the block is invalid and it is due to locktime i think based on the errors i see. but why would bitcoind set its locktime to a time that is invalid or null? block verification is failing, and it only is in regtest mode, testnet is fine meaning i am missing something in my regtest node i cant figure out. either it is stuck in intialblockdownload, or the locktime is off somehow, or some otehr time issue causing a failure of verification.

bitcoind regtest nodes sync but still have the timing mishap.


1. what is a timing mishap? i cant find any info on it ANYWHERE, maybe i am not searching right. why would this be happening?
2. what are transaction verification flags? and how can i see them in bitcoin-cli?
3. how can i see if bitcoind is serving the block or disconnecting before it serves the block, is there any way to get more detailed logging? or a way to snoop on the communication? can i tell who initiated the connection termination?
4. can a protocol version 70000 communicate effectively with 70015?
5. is there any reason a regtest enviornment would act differently from mainnet in regards to block/transaction flags or the way the locktimes are set? i really dont know where to even look here. all i know is bitcoind nodes sync but have timing mishaps, bitcoinj cant pull FULL .


for the record, bitcoinjs full node code mirrors satoshi's exactly, it has to, so i have read. so im not sure how it communicates but i assume the same way bitcoind clients communicate.


and if you do have experience iwth bitcoinj, please check my other thread, i will be eternally greatful to anybody who can help. feel free to message in private as well.



bitcoind running with this:


and the log from bitcoind:

Code:

2017-10-08 03:29:13 Bitcoin version v0.15.0.1
2017-10-08 03:29:13 InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
2017-10-08 03:29:13 Validating signatures for all blocks.
2017-10-08 03:29:13 Using the 'standard' SHA256 implementation
2017-10-08 03:29:13 Using RdRand as an additional entropy source
2017-10-08 03:29:14 RandAddSeedPerfmon: 605584 bytes
2017-10-08 03:29:14 Default data directory C:\Bitcoin
2017-10-08 03:29:14 Using data directory C:\regtest
2017-10-08 03:29:14 Using config file C:/bitcoin.conf
2017-10-08 03:29:14 Using at most 125 automatic connections (2048 file descriptors available)
2017-10-08 03:29:14 Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2017-10-08 03:29:14 Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2017-10-08 03:29:14 Using 4 threads for script verification
2017-10-08 03:29:14 scheduler thread start
2017-10-08 03:29:14 Allowing HTTP connections from: 127.0.0.0/8 ::1/128
2017-10-08 03:29:14 Binding RPC on address ::1 port 8444
2017-10-08 03:29:14 libevent: getaddrinfo: nodename nor servname provided, or not known
2017-10-08 03:29:14 Binding RPC on address ::1 port 8444 failed.
2017-10-08 03:29:14 Binding RPC on address 127.0.0.1 port 8444
2017-10-08 03:29:14 Initialized HTTP server
2017-10-08 03:29:14 HTTP: creating work queue of depth 16
2017-10-08 03:29:14 Starting RPC
2017-10-08 03:29:14 Starting HTTP RPC server
2017-10-08 03:29:14 Config options rpcuser and rpcpassword will soon be deprecated. Locally-run instances may remove rpcuser to use cookie-based auth, or may be replaced with rpcauth. Please see share/rpcuser for rpcauth auth generation.
2017-10-08 03:29:14 Registering HTTP handler for / (exactmatch 1)
2017-10-08 03:29:14 Registering HTTP handler for /wallet/ (exactmatch 0)
2017-10-08 03:29:14 Starting HTTP server
2017-10-08 03:29:14 HTTP: starting 4 worker threads
2017-10-08 03:29:14 init message: Verifying wallet(s)...
2017-10-08 03:29:14 Entering http event loop
2017-10-08 03:29:14 Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
2017-10-08 03:29:14 Using wallet wallet.dat
2017-10-08 03:29:14 CDBEnv::Open: LogDir=C:\regtest\database ErrorFile=C:\regtest\db.log
2017-10-08 03:29:14 Cache configuration:
2017-10-08 03:29:14 * Using 2.0MiB for block index database
2017-10-08 03:29:14 * Using 8.0MiB for chain state database
2017-10-08 03:29:14 * Using 440.0MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
2017-10-08 03:29:14 init message: Loading block index...
2017-10-08 03:29:14 Opening LevelDB in C:\regtest\blocks\index
2017-10-08 03:29:14 Recovering log #12
2017-10-08 03:29:14 Level-0 table #14: started
2017-10-08 03:29:14 Level-0 table #14: 179 bytes OK
2017-10-08 03:29:14 Delete type=0 #12
2017-10-08 03:29:14 Delete type=3 #10
2017-10-08 03:29:14 Opened LevelDB successfully
2017-10-08 03:29:14 Compacting 4@0 + 0@1 files
2017-10-08 03:29:14 Using obfuscation key for C:\regtest\blocks\index: 0000000000000000
2017-10-08 03:29:14 LoadBlockIndexDB: last block file = 0
2017-10-08 03:29:14 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=102, size=24012, heights=0...101, time=2011-02-02...2017-10-06)
2017-10-08 03:29:14 Checking all blk files are present...
2017-10-08 03:29:14 LoadBlockIndexDB: transaction index disabled
2017-10-08 03:29:14 Opening LevelDB in C:\regtest\chainstate
2017-10-08 03:29:14 Recovering log #13
2017-10-08 03:29:14 Level-0 table #15: started
2017-10-08 03:29:14 Generated table #16@0: 105 keys, 14217 bytes
2017-10-08 03:29:14 Compacted 4@0 + 0@1 files => 14217 bytes
2017-10-08 03:29:14 Level-0 table #15: 308 bytes OK
2017-10-08 03:29:14 compacted to: files[ 0 1 0 0 0 0 0 ]
2017-10-08 03:29:14 Delete type=2 #5
2017-10-08 03:29:14 Delete type=2 #8
2017-10-08 03:29:14 Delete type=2 #11
2017-10-08 03:29:14 Delete type=2 #14
2017-10-08 03:29:14 Delete type=0 #13
2017-10-08 03:29:14 Delete type=3 #11
2017-10-08 03:29:14 Opened LevelDB successfully
2017-10-08 03:29:14 Using obfuscation key for C:\regtest\chainstate: dd6ff88733cb0b53
2017-10-08 03:29:14 Loaded best chain: hashBestChain=35ebf25b797550e724f1877bc1f64531efce23eae68d804fc9301b8754b67cd2 height=101 date=2017-10-06 05:28:27 progress=1.000000
2017-10-08 03:29:14 init message: Rewinding blocks...
2017-10-08 03:29:14 Writing final batch of 0.00 MiB
2017-10-08 03:29:14 Committed 0 changed transaction outputs (out of 0) to coin database...
2017-10-08 03:29:14 init message: Verifying blocks...
2017-10-08 03:29:14 Verifying last 6 blocks at level 3
2017-10-08 03:29:14 [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
2017-10-08 03:29:14 No coin database inconsistencies in last 7 blocks (7 transactions)
2017-10-08 03:29:14  block index              94ms
2017-10-08 03:29:14 Reading estimates: 190 buckets counting confirms up to 48 blocks
2017-10-08 03:29:14 Reading estimates: 190 buckets counting confirms up to 12 blocks
2017-10-08 03:29:14 Reading estimates: 190 buckets counting confirms up to 1008 blocks
2017-10-08 03:29:14 init message: Loading wallet...
2017-10-08 03:29:14 nFileVersion = 150001
2017-10-08 03:29:14 Keys: 2003 plaintext, 0 encrypted, 2003 w/ metadata, 2003 total
2017-10-08 03:29:14  wallet                   78ms
2017-10-08 03:29:14 setKeyPool.size() = 2000
2017-10-08 03:29:14 mapWallet.size() = 101
2017-10-08 03:29:14 mapAddressBook.size() = 1
2017-10-08 03:29:14 mapBlockIndex.size() = 102
2017-10-08 03:29:14 nBestHeight = 101
2017-10-08 03:29:14 Imported mempool transactions from disk: 0 successes, 0 failed, 0 expired
2017-10-08 03:29:14 Bound to 127.0.0.1:18444
2017-10-08 03:29:14 Bound to 127.0.0.1:18444
2017-10-08 03:29:14 init message: Loading P2P addresses...
2017-10-08 03:29:14 Loaded 0 addresses from peers.dat  0ms
2017-10-08 03:29:14 init message: Loading banlist...
2017-10-08 03:29:14 Loaded 0 banned node ips/subnets from banlist.dat  0ms
2017-10-08 03:29:14 init message: Starting network threads...
2017-10-08 03:29:14 net thread start
2017-10-08 03:29:14 init message: Done loading
2017-10-08 03:29:14 opencon thread start
2017-10-08 03:29:14 dnsseed thread start
2017-10-08 03:29:14 addcon thread start
2017-10-08 03:29:14 msghand thread start
2017-10-08 03:29:14 Loading addresses from DNS seeds (could take a while)
2017-10-08 03:29:14 0 addresses found from DNS seeds
2017-10-08 03:29:14 dnsseed thread exit
2017-10-08 03:30:07 Added connection peer=0
2017-10-08 03:30:07 connection from 127.0.0.1:19377 accepted
2017-10-08 03:30:07 received: version (103 bytes) peer=0
2017-10-08 03:30:07 sending version (104 bytes) peer=0
2017-10-08 03:30:07 send version message: version 70015, blocks=101, us=[::]:0, peer=0
2017-10-08 03:30:07 sending verack (0 bytes) peer=0
2017-10-08 03:30:07 receive version message: /bitcoinj:0.14.5/: version 70001, blocks=0, us=127.0.0.1:18444, peer=0
2017-10-08 03:30:07 added time data, samples 2, offset +0 (+0 minutes)
2017-10-08 03:30:07 sending alert (168 bytes) peer=0
2017-10-08 03:30:07 received: verack (0 bytes) peer=0
2017-10-08 03:30:07 sending ping (8 bytes) peer=0
2017-10-08 03:30:07 received: pong (8 bytes) peer=0
2017-10-08 03:30:07 pong peer=0: Timing mishap, 5d8e9xxxxxx54126 expected, 5d8e9xxxxxx54126 received, 8 bytes
2017-10-08 03:30:09 received: ping (8 bytes) peer=0
2017-10-08 03:30:09 sending pong (8 bytes) peer=0
2017-10-08 03:30:11 received: ping (8 bytes) peer=0
2017-10-08 03:30:11 sending pong (8 bytes) peer=0
2017-10-08 03:30:12 received: getblocks (69 bytes) peer=0
2017-10-08 03:30:12 getblocks 1 to end limit 500 from peer=0
2017-10-08 03:30:12 sending inv (3637 bytes) peer=0
2017-10-08 03:30:12 received: getdata (3637 bytes) peer=0
2017-10-08 03:30:12 received getdata (101 invsz) peer=0
2017-10-08 03:30:12 received getdata for: block 237446d4xxxxxxxxxxxab151a393df9a42731c894fe087379bcc24484820c843 peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 socket closed
2017-10-08 03:30:12 sending block (226 bytes) peer=0
2017-10-08 03:30:12 disconnecting peer=0
2017-10-08 03:30:12 Cleared nodestate for peer=0
2017-10-08 03:30:14 Added connection peer=1
2017-10-08 03:30:14 connection from 127.0.0.1:19378 accepted
2017-10-08 03:30:14 received: version (103 bytes) peer=1
2017-10-08 03:30:14 sending version (104 bytes) peer=1
2017-10-08 03:30:14 send version message: version 70015, blocks=101, us=[::]:0, peer=1
2017-10-08 03:30:14 sending verack (0 bytes) peer=1
2017-10-08 03:30:14 receive version message: /bitcoinj:0.14.5/: version 70001, blocks=0, us=127.0.0.1:18444, peer=1
2017-10-08 03:30:14 sending alert (168 bytes) peer=1
2017-10-08 03:30:14 received: verack (0 bytes) peer=1
2017-10-08 03:30:14 sending ping (8 bytes) peer=1
2017-10-08 03:30:14 received: getblocks (69 bytes) peer=1
2017-10-08 03:30:14 getblocks 1 to end limit 500 from peer=1
2017-10-08 03:30:14 sending inv (3637 bytes) peer=1
2017-10-08 03:30:14 received: pong (8 bytes) peer=1
2017-10-08 03:30:14 pong peer=1: Timing mishap, 90exxxxxxf137c88 expected, 90exxxxxxf137c88 received, 8 bytes
2017-10-08 03:30:14 received: getdata (3637 bytes) peer=1
2017-10-08 03:30:14 received getdata (101 invsz) peer=1
2017-10-08 03:30:14 received getdata for: block 237446d4xxxxxxxxxxxab151a393df9a42731c894fe087379bcc24484820c843 peer=1
2017-10-08 03:30:14 sending block (226 bytes) peer=1
2017-10-08 03:30:14 sending block (226 bytes) peer=1
2017-10-08 03:30:14 socket closed

running bitcoind with (C is not the actual path):

Code:

bitcoind -regtest -listen -datadir=C:/ -conf=C:/bitcoin.conf -whitebind=127.0.0.1:18444 -whitelist=127.0.0.1

Peer info on bitcoind node:

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
    }
  }

[achow101]

1. what is a timing mishap? i cant find any info on it ANYWHERE, maybe i am not searching right. why would this be happening?

A timing mishap in this context (with the pong message) is a pong message which has an old nonce value that is not expected. Can you please post your debug.log file with those values unredacted? Without being able to see what is actually being reported, it is hard to say what is wrong.

2. what are transaction verification flags? and how can i see them in bitcoin-cli?

Transaction verification flags are the rules that are used in validating transactions. These rules include the standardness rules and other node policy rules that are not consensus rules. You cannot see what they are in bitcoin-cli; you will have to look at the source code.

3. how can i see if bitcoind is serving the block or disconnecting before it serves the block, is there any way to get more detailed logging? or a way to snoop on the communication? can i tell who initiated the connection termination?

Run Bitcoin Core with the -debug option. You are already running with debug=net which is enough to determine whether a block is served before disconnecting. Blocks are definitely being sent before the socket is closed and disconnected.

4. can a protocol version 70000 communicate effectively with 70015?

Yes.

5. is there any reason a regtest enviornment would act differently from mainnet in regards to block/transaction flags or the way the locktimes are set? i really dont know where to even look here. all i know is bitcoind nodes sync but have timing mishaps, bitcoinj cant pull FULL .

The block and transaction verification flags have nothing to do with the networking. All consensus rules are the same, but some node policy rules are relaxed to allow for non-standard transactions. locktimes are a consensus rule.

for the record, bitcoinjs full node code mirrors satoshi's exactly, it has to, so i have read. so im not sure how it communicates but i assume the same way bitcoind clients communicate.

The protocol has changed since the full node stuff was written and it has not really been updated since. It is also experimental.

[Bitdev181]

hello,

debug.log file is empty i believe since i use printtoconsole.

and im not running debug=net, im running debug=1 which should be full debug or the same as -debug in the command line right? im also mixing cmd flags and bitcoin.conf file

i will look in to how to get a proper debug, i thought i had full debug.  i responded with the bitcoinj code to other thread.

UPDATE: got rid of printtoconsole and debug=1 in config, set -debug flag in command line when running bitcoind, same error log, no additional info. i will try some other flags and see if i pull more info somehow.

[jennywhzz]

Running side by side is tricky. Start with the Java logs, and try to track it in there. I would always blame the Java before the core. Change the logging settings to provide info on each step and go from there. Use those time stamps and cross reference with the core. Maybe use a small script in between to simply hand off the data from btc to the core or vice versa.

[Bitdev181]

Well in the main thread i had somebody point out that it was the java, you are 100% correct.

however why is it that in testnet a blocks version is = 1 (why my node works with testnet)

but in regtest i have some very high block version because regtest is generating blocks with all sorts of verification requirements.


is there a way to fix this to mirror mainnet properly so bitcoinj can work?

also does mainnet start with version=1 and slowly increase as new BIP versions were released? why cant regtest do this too?