Quote from: clayop on August 18, 2015, 07:26:31 pm

Well done puppies. I think we are not that bad bad test witnesses 

  You guys have done a great job.   If we could find a way to reliably reproduce this with just a few nodes that would be very helpful.

Try run a node in a unstable network? With limited bandwidth, or heavy networking load, high latency etc.

The network is still up and generating blocks on at least three different systems. 

Code: [Select]

  "head_block_num": 113869,
  "head_block_id": "0001bccd0acdf8b05c58b6cc5e6e36d717de523c",
  "head_block_age": "2 seconds old",
  "next_maintenance_time": "4 minutes in the future",
  "chain_id": "081401ede64c8fe30b23c91d7ab8750103acb1a39548a866fb562f2edf4627d6",
It seems like your node did fork and now wont accept the proper chain.

Code: [Select]

get_block 72042
{
  "previous": "000119696d1d31776e6431586e14fd2e4c0b4f58",
  "timestamp": "2015-08-18T02:07:59",
  "witness": "1.6.1435",
  "next_secret_hash": "72dcf0475fa5d0c145a235f590b5be3597c17753",
  "previous_secret": "2813946aacd0bfda5541bf243f5bc47aee51e314",
  "transaction_merkle_root": "0000000000000000000000000000000000000000",
  "extensions": [],
  "witness_signature": "201506e5034d1df8627196bc97b5293eed3efbb6391a256789ca4a6912f169b45b51045f55f9be468a2db485bfcc4952996e10d1f4be0cc1c0eef2764470649035",
  "transactions": []
}
locked >>> get_block 72043
get_block 72043
{
  "previous": "0001196a1eb9d0e2021fd4f6ac9fe452ea46d4b3",
  "timestamp": "2015-08-18T02:08:00",
  "witness": "1.6.0",
  "next_secret_hash": "031a792684e0d99dab315ce6aea4fa92c85c6707",
  "previous_secret": "cd722b49f39a4b7160e081ae2c26cdf71f8e9194",
  "transaction_merkle_root": "0000000000000000000000000000000000000000",
  "extensions": [],
  "witness_signature": "1f64cf6d9e48683ed2259772c5006c0a1ec195dc280c59b5941250fa1581e8b86c0d32ed49d47d9d57cc87b3088e2f52bc15c7dc500955fa334864a3ed7b08be63",
  "transactions": []
}
locked >>> get_block 72044
get_block 72044
{
  "previous": "0001196bf9cf506fb01511e20c8566694b952a7d",
  "timestamp": "2015-08-18T02:08:01",
  "witness": "1.6.4",
  "next_secret_hash": "42899548ec99624cb2102330c429562510ef09a0",
  "previous_secret": "2777b474efe4774a69d716f61b5cf156deb3a232",
  "transaction_merkle_root": "0000000000000000000000000000000000000000",
  "extensions": [],
  "witness_signature": "1f02312f66e1dcf78335d1c5ee999181cd3a0191d927d48376fa5702a493d418514d01eb530328c2dee956d5824103b8576e7974049e0d414eab142fd3ddbbe991",
  "transactions": []
}
locked >>>
im curious is your block 72042 matches mine.

Looks like my node produced a #72042 block but failed to broadcast it in time (networking issue) then got stuck. It got #72043 and following blocks but failed to push them into chain database, because those blocks are linked to another #72042, but it didn't request for that #72042.
There could be an issue in code. Maybe current code just throw out an exception in this case. Maybe it's better to temporarily save the new block and request for it's previous block if it's not same as the one in current fork.

Just restarted my node and catching up.

The node is in China, network condition will be OK in next 8 hours or so (mid-night), and may go bad again after that. 

//update: my node should have produced a #72042 block but not #72043.

Quote from: betax on August 17, 2015, 04:14:25 pm

I was producing blocks, but every so often I had the ntp error.

I have seen that NTP error from time to time myself.  We will look into it.

Vikram and I have reviewed the testnet and have identified a patch that would allow us to revive the existing test net by specifying a checkpoint.  Once we are sure we can revive the testnet we will start a new network with at least 100 witness slots so that it is less likely for a few bad apples to result in this issue.

It could be that you produced blocks on a fork.  If any of you have evidence that you were on a fork (have a block that wasn't included in the main chain) then that is something I am very interested in.

Looks like I'm on a fork right now, stopped syncing and stopped producing blocks. Logs of production witness are here. It perhaps caused by slow network connection to other peers.

2015-08-18T02:04:12 th_a:Witness Block Production block_production_loo ] slot: 1 scheduled_witness: 1.6.6 scheduled_time: 2015-08-18T0
2:04:13 now: 2015-08-18T02:04:13                  witness.cpp:239
2015-08-18T02:04:13 th_a:invoke handle_block         handle_block ] Got block #71842 from network                       application.cp
p:342
2015-08-18T02:04:13  th_a:invoke get_item             get_item ] Request for item {"item_type":1001,"item_hash":"000118a2245ede2df39a1
f4ae6da4e12f62f8232"}                     application.cpp:437
2015-08-18T02:04:13  th_a:invoke get_item             get_item ] Serving up block #71842                        application.cpp:445
2015-08-18T02:04:13 th_a:Witness Block Production block_production_loo ] slot: 1 scheduled_witness: 1.6.5155 scheduled_time: 2015-08-1
8T02:04:14 now: 2015-08-18T02:04:14                       witness.cpp:239
2015-08-18T02:04:13 th_a:Witness Block Production block_production_loo ] Witness 1.6.5155 production slot has arrived; generating a bl
ock now...                        witness.cpp:242
2015-08-18T02:04:13 th_a:Witness Block Production block_production_loo ] Generated block #71843 with timestamp 2015-08-18T02:04:14 at
time 2015-08-18T02:04:14                  witness.cpp:255
2015-08-18T02:04:13  th_a:invoke get_item             get_item ] Request for item {"item_type":1001,"item_hash":"000118a30cd6a49579d36
ad1217b098a544a798a"}                     application.cpp:437
2015-08-18T02:04:13  th_a:invoke get_item             get_item ] Serving up block #71843                        application.cpp:445
2015-08-18T02:04:14 th_a:Witness Block Production block_production_loo ] slot: 1 scheduled_witness: 1.6.1439 scheduled_time: 2015-08-1
8T02:04:15 now: 2015-08-18T02:04:15                       witness.cpp:239
2015-08-18T02:04:15 th_a:Witness Block Production block_production_loo ] slot: 2 scheduled_witness: 1.6.1 scheduled_time: 2015-08-18T0
2:04:16 now: 2015-08-18T02:04:16                  witness.cpp:239
2015-08-18T02:04:16 th_a:Witness Block Production block_production_loo ] slot: 3 scheduled_witness: 1.6.0 scheduled_time: 2015-08-18T0
2:04:17 now: 2015-08-18T02:04:17                  witness.cpp:239
2015-08-18T02:04:17 th_a:Witness Block Production block_production_loo ] slot: 4 scheduled_witness: 1.6.5 scheduled_time: 2015-08-18T0
2:04:18 now: 2015-08-18T02:04:18                  witness.cpp:239
2015-08-18T02:04:18 th_a:Witness Block Production block_production_loo ] slot: 5 scheduled_witness: 1.6.4 scheduled_time: 2015-08-18T0
2:04:19 now: 2015-08-18T02:04:19                  witness.cpp:239
2015-08-18T02:04:19 th_a:Witness Block Production block_production_loo ] slot: 6 scheduled_witness: 1.6.1435 scheduled_time: 2015-08-1
8T02:04:20 now: 2015-08-18T02:04:20                       witness.cpp:239
2015-08-18T02:04:20  th_a:invoke get_item             get_item ] Request for item {"item_type":1001,"item_hash":"000118a30cd6a49579d36
ad1217b098a544a798a"}                     application.cpp:437
2015-08-18T02:04:20  th_a:invoke get_item             get_item ] Serving up block #71843                        application.cpp:445
2015-08-18T02:04:20 th_a:invoke handle_block         handle_block ] Got block #71844 from network                       application.cp
p:342
2015-08-18T02:04:20 th_a:invoke handle_block         handle_block ] Error when pushing block:
10 assert_exception: Assert Exception
itr != _index.get<block_id>().end():
    {}
    th_a  fork_database.cpp:51 push_block

    {"new_block":{"previous":"000118a3ca0d1e6e5737f248ddb53836aa6212e4","timestamp":"2015-08-18T02:04:16","witness":"1.6.1","next_secret_hash":"6449e9c56a67b58d886f2064e929f17f94fe78f1","previous_secret":"68c24af208df75b7b3d6570206492ef3bee5c5b9","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f4becadfa61a394b550ce6d086fb5d9eb3da8c883ac703048c7baee139414089f6777d1c03787d982160d23ecef7df3df3ea8713c15441247c30c4ef5568e22ac","transactions":[]}}
    th_a  db_block.cpp:173 _push_block                  application.cpp:364
2015-08-18T02:04:20 th_a:Witness Block Production block_production_loo ] slot: 7 scheduled_witness: 1.6.2 scheduled_time: 2015-08-18T02:04:21 now: 2015-08-18T02:04:21                  witness.cpp:239
2015-08-18T02:04:21 th_a:invoke handle_block         handle_block ] Got block #71845 from network                       application.cpp:342
2015-08-18T02:04:21 th_a:invoke handle_block         handle_block ] Error when pushing block:
10 assert_exception: Assert Exception
itr != _index.get<block_id>().end():
    {}
    th_a  fork_database.cpp:51 push_block

    {"new_block":{"previous":"000118a4b95f7448500f912995feeffe47e61773","timestamp":"2015-08-18T02:04:17","witness":"1.6.0","next_secret_hash":"6449e9c56a67b58d886f2064e929f17f94fe78f1","previous_secret":"68c24af208df75b7b3d6570206492ef3bee5c5b9","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"2041523e0275f0ce506c797145c86f2b5ed5fb7d9eb9cff0f1cb9364e5a06c327e535dfd76846d56824d41ad69e502d2b88679b7060b33200128991dacf92f97ae","transactions":[]}}
    th_a  db_block.cpp:173 _push_block                  application.cpp:364


The observer witness node is stuck as well, haven't find related log yet.

//EDIT: console log of observer node is here.
251230ms th_a       application.cpp:342           handle_block         ] Got block #71840 from network
252602ms th_a       application.cpp:342           handle_block         ] Got block #71841 from network
253600ms th_a       application.cpp:342           handle_block         ] Got block #71842 from network
253998ms th_a       application.cpp:342           handle_block         ] Got block #71843 from network
440984ms th_a       application.cpp:486           get_blockchain_synop ] reference_point: 0000000000000000000000000000000000000000 num
ber_of_blocks_after_reference_point: 0 result: ["000018a317c85eac7ed13615354fcef049951d86","000098a3e1624c807fd57d019d0dcf58844905ac",
"0000d8a3f2164ee15e1d2404cf5815daaf024091","0000f8a34a36120b0ccf1ed468f1e5c1a0b81239","000108a338ff000b4ea31a71938f19d6668a330e","0001
10a3079a6cdffeb63507c7c4a44406221c1b","000114a31f31315fe4d4f9a3c18923029b506111","000116a318c63b35c2dbdd46e674b4c49dcf0673","000117a3c
2bdf2658c7d67a5f9040e65ac98a02d","00011823272051adb5851eb6617b11145a03979e","0001186341115fddf7f06780b5164e5254324f96","000118833ab2b2
fc44045ebb63376313df4cf712","0001189332e4dc39800f335bbd4cf10135617a33","0001189b4b78dec8eb8efebeb5b9fab06e6647ad","0001189fcd7f19f8469
b604041fd14a225ce5bae","000118a1ac5579df7e3f7952bf3889e7f6cc8413","000118a2245ede2df39a1f4ae6da4e12f62f8232","000118a30cd6a49579d36ad1
217b098a544a798a"]
466784ms th_a       application.cpp:486           get_blockchain_synop ] reference_point: 0000000000000000000000000000000000000000 num
ber_of_blocks_after_reference_point: 0 result: ["000018a317c85eac7ed13615354fcef049951d86","000098a3e1624c807fd57d019d0dcf58844905ac",
"0000d8a3f2164ee15e1d2404cf5815daaf024091","0000f8a34a36120b0ccf1ed468f1e5c1a0b81239","000108a338ff000b4ea31a71938f19d6668a330e","0001
10a3079a6cdffeb63507c7c4a44406221c1b","000114a31f31315fe4d4f9a3c18923029b506111","000116a318c63b35c2dbdd46e674b4c49dcf0673","000117a3c
2bdf2658c7d67a5f9040e65ac98a02d","00011823272051adb5851eb6617b11145a03979e","0001186341115fddf7f06780b5164e5254324f96","000118833ab2b2
fc44045ebb63376313df4cf712","0001189332e4dc39800f335bbd4cf10135617a33","0001189b4b78dec8eb8efebeb5b9fab06e6647ad","0001189fcd7f19f8469
b604041fd14a225ce5bae","000118a1ac5579df7e3f7952bf3889e7f6cc8413","000118a2245ede2df39a1f4ae6da4e12f62f8232","000118a30cd6a49579d36ad1
217b098a544a798a"]


There are two arguments:  -w "1.6.X" means produce for that witness, enable-stale means produce alone.

Thanks. Just restarted my witness without enable-stale parameter and it works!

By the way how to "cleanly" exit the witness node? It takes much time to replay while restarting.

Quote from: abit on August 17, 2015, 11:44:33 pm

Without '--enable-stale-production' my witness doesn't produce blocks.
It's really confusing. Maybe it's better to have 2 parameters: '--enable-block-production' and '--enable-stale-production'.

I thought the same last night, but I just set up my node earlier without the stale production and it was producing blocks when I left.

Maybe because the "Generated block" lines in the console log are in white color, so I didn't notice them.
540991ms th_a       witness.cpp:242               block_production_loo ] Witness 1.6.5155 production slot has arrived; generating a bl
ock now...
540992ms th_a       witness.cpp:255               block_production_loo ] Generated block #66220 with timestamp 2015-08-18T00:09:01 at
time 2015-08-18T00:09:01

And this line of log is in blue:
884991ms th_a       witness.cpp:191               operator()           ] Not producing block because production is disabled.
8
But the real reason of 'production disabled' is "not enabled stale production && it's stale now "? I would not get confused if the log says "... because stale production is disabled".

The test net died, but I started another one, so if you want to test until another official one comes up replace the url in bytemasters command with 45.55.6.216:1776

I'm in and producing blocks, witness 1.6.5155.
Current IP/port of my observing/seed node is 114.92.254.159:62016.

Command of witness node for observing:
./witness_node --rpc-endpoint "127.0.0.1:8170"  --genesis-json "aug-14-test-genesis.json" --data-dir="testnet_puppies_ob" -s "45.55.6.216:1776" --p2p-endpoint "0.0.0.0:62016"

Command of CLI wallet for observing:
./cli_wallet -w wallet-testnet-puppies-ob.json --chain-id 081401ede64c8fe30b23c91d7ab8750103acb1a39548a866fb562f2edf4627d6 -s ws://127.0.0.1:8170

Command of witness node for block producing:
./witness_node --rpc-endpoint "127.0.0.1:8190"  --genesis-json "aug-14-test-genesis.json" --data-dir="testnet_puppies_prod" -s "45.55.6.216:1776" --witness-id '"1.6.5155"' --private-key '["MY_SIGNING_KEY","PRIVATE_KEY_OF_MY_SIGNING_KEY"]'

Command of CLI wallet for block producing:
./cli_wallet -w wallet-testnet-puppies-prod.json --chain-id 081401ede64c8fe30b23c91d7ab8750103acb1a39548a866fb562f2edf4627d6 -s ws://127.0.0.1:8190

//Edit: removed the '--enable-stale-production' parameter.

My test witness missed all blocks since I haven't enabled block production.. 

My node is stuck at 134419 as well.. is it on the right fork?
I'm not running with --enable-stale-production though..

Code: [Select]

info
{
  "head_block_num": 134419,
  "head_block_id": "00020d137298dab08e3147893e61dfed75ad7d0e",
  "head_block_age": "8 hours old",
  "next_maintenance_time": "8 hours ago",
  "chain_id": "081401ede64c8fe30b23c91d7ab8750103acb1a39548a866fb562f2edf4627d6",
  "active_witnesses": [
    "1.6.0",
    "1.6.1",
    "1.6.2",
    "1.6.3",
    "1.6.4",
    "1.6.1435",
    "1.6.1439",
    "1.6.1446",
    "1.6.5155",
    "1.6.5156"
  ],
  "active_committee_members": [
    "1.5.0",
    "1.5.1",
    "1.5.2",
    "1.5.3",
    "1.5.4",
    "1.5.5",
    "1.5.6",
    "1.5.7",
    "1.5.8",
    "1.5.9"
  ],
  "entropy": "e8f56f18210fc56faa891342f94cbade418c834f"
}


Edit: I'll try to restart with BM's seed node only

Here is log.
2015-08-16T18:06:34 p2p:message read_loop process_block_during ] received a sync block from peer 104.200.28.117:61705
        node.cpp:3073
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks process_backlog_of_s ] in process_backlog_of_sync_blocks                 node.c
pp:2959
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks process_backlog_of_s ] currently 1 blocks in the process of being handled
                        node.cpp:2965
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks process_backlog_of_s ] currently 1 sync items to consider
        node.cpp:2995
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks process_backlog_of_s ] currently 0 sync items to consider
        node.cpp:2995
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks process_backlog_of_s ] leaving process_backlog_of_sync_blocks, 1 processed
                       node.cpp:3056
2015-08-16T18:06:34 p2p:process_backlog_of_sync_blocks trigger_fetch_sync_i ] Triggering fetch sync items loop now
        node.cpp:1081
2015-08-16T18:06:34 p2p:fetch_sync_items_loop fetch_sync_items_loo ] beginning another iteration of the sync items loop
        node.cpp:1020
2015-08-16T18:06:34 p2p:fetch_sync_items_loop fetch_sync_items_loo ] no sync items to fetch right now, going to sleep
        node.cpp:1070
2015-08-16T18:06:34 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] in send_sync_block_to_node_delegate()
        node.cpp:2777
2015-08-16T18:06:34 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] Failed to push sync block 134318 (id:00020cae30db6d247c1b3e356a55e93808e1290d): client rejected sync block sent by peer: {"code":10,"name":"assert_exception","message":"Assert Exception","stack":[{"context":{"level":"error","file":"fork_database.cpp","line":51,"method":"push_block","hostname":"","thread_name":"th_a","timestamp":"2015-08-16T18:06:34"},"format":"itr != _index.get<block_id>().end(): ","data":{}},{"context":{"level":"warn","file":"db_block.cpp","line":173,"method":"_push_block","hostname":"","thread_name":"th_a","timestamp":"2015-08-16T18:06:34"},"format":"","data":{"new_block":{"previous":"00020cade4b2e23a805d33e5585cd501b327efd5","timestamp":"2015-08-16T08:55:51","witness":"1.6.1435","next_secret_hash":"852c62c5a7e927cfff752276b543b1731a58b42f","previous_secret":"ed9b9f8a4624bbb6eb2dba63336b2643a5b5561b","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f06bab5ea47138f12a31f15fb82962c87d5679b3e176002b78422f6143301870676208b51eb11bf4320a05282171e95f5c33992e3e4034e63eaf1b57f087a8827","transactions":[]}}},{"context":{"level":"warn","file":"application.cpp","line":373,"method":"handle_block","hostname":"","thread_name":"th_a","timestamp":"2015-08-16T18:06:34"},"format":"","data":{"blk_msg":{"block":{"previous":"00020cade4b2e23a805d33e5585cd501b327efd5","timestamp":"2015-08-16T08:55:51","witness":"1.6.1435","next_secret_hash":"852c62c5a7e927cfff752276b543b1731a58b42f","previous_secret":"ed9b9f8a4624bbb6eb2dba63336b2643a5b5561b","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f06bab5ea47138f12a31f15fb82962c87d5679b3e176002b78422f6143301870676208b51eb11bf4320a05282171e95f5c33992e3e4034e63eaf1b57f087a8827","transactions":[]},"block_id":"00020cae30db6d247c1b3e356a55e93808e1290d"},"sync_mode":true}}]}                     node.cpp:2813
2015-08-16T18:06:34 p2p:send_sync_block_to_node_delegate send_sync_block_to_n ] disconnecting client 104.200.28.117:61705 because it offered us the rejected block                      node.cpp:2928
2015-08-16T18:06:34 p2p:send_sync_block_to_node_delegate         send_message ] peer_connection::send_message() enqueueing message of type 5011 for peer 104.200.28.117:61705                   peer_connection.cpp:365
2015-08-16T18:06:34 p2p:send_sync_block_to_node_delegate send_queueable_messa ] peer_connection::send_message() is firing up send_queued_message_task                   peer_connection.cpp:354
2015-08-16T18:06:34 p2p:send_queued_messages_task              counter ] entering peer_connection::send_queued_messages_task()
                peer_connection.cpp:279
2015-08-16T18:06:34 p2p:send_queued_messages_task send_queued_messages ] peer_connection::send_queued_messages_task() calling message_oriented_connection::send_message() to send message of type 5011 for peer 104.200.28.117:61705                    peer_connection.cpp:291


Does it mean that BM's node are on a wrong fork?
... received a sync block from peer 104.200.28.117:61705 ...
... block 134318 (id:00020cae30db6d247c1b3e356a55e93808e1290d) ...
... "timestamp":"2015-08-16T18:06:34" ...
{"previous":"00020cade4b2e23a805d33e5585cd501b327efd5","timestamp":"2015-08-16T08:55:51"
...


My node is stuck at 134419 as well.. is it on the right fork?
I'm not running with --enable-stale-production though..
info
{
  "head_block_num": 134419,
  "head_block_id": "00020d137298dab08e3147893e61dfed75ad7d0e",
  "head_block_age": "8 hours old",
  "next_maintenance_time": "8 hours ago",
  "chain_id": "081401ede64c8fe30b23c91d7ab8750103acb1a39548a866fb562f2edf4627d6",
  "active_witnesses": [
    "1.6.0",
    "1.6.1",
    "1.6.2",
    "1.6.3",
    "1.6.4",
    "1.6.1435",
    "1.6.1439",
    "1.6.1446",
    "1.6.5155",
    "1.6.5156"
  ],
  "active_committee_members": [
    "1.5.0",
    "1.5.1",
    "1.5.2",
    "1.5.3",
    "1.5.4",
    "1.5.5",
    "1.5.6",
    "1.5.7",
    "1.5.8",
    "1.5.9"
  ],
  "entropy": "e8f56f18210fc56faa891342f94cbade418c834f"
}


Edit: I'll try to restart with BM's seed node only