Title: Bitcoind timing mishap?
Post by: Bitdev181 on October 08, 2017, 04:02:11 AM
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:
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): 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: { "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 } }
Title: Re: Bitcoind timing mishap?
Post by: achow101 on October 08, 2017, 04:25:48 AM
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.
Title: Re: Bitcoind timing mishap?
Post by: Bitdev181 on October 08, 2017, 07:09:11 PM
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.
Title: Re: Bitcoind timing mishap?
Post by: jennywhzz on October 10, 2017, 03:40:15 PM
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.
Title: Re: Bitcoind timing mishap?
Post by: Bitdev181 on October 10, 2017, 10:13:33 PM
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?
|