October 5 Test Network

[rnglab]

I am getting this sometimes

Code: [Select]

3033114ms th_a       db_block.cpp:191              _push_block          ] Failed to push new block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block
3033116ms th_a       application.cpp:425           handle_block         ] Error when pushing block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block

    {"new_block":{"previous":"0000e55de39c07283d1779c89018c18206bfa9f2","timestamp":"2015-10-07T17:50:33","witness":"1.6.37","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f19b73fc82aa7519e28f34b1f8e10f63da27365c8e5699fd9f77c0ee1f4c4b02841560af821e3ec8e71f72264934140c7fb2cdd78e0f91920edc7b8cba9c33cfb","transactions":[]}}
    th_a  db_block.cpp:197 _push_block


I see the same. Perhaps something wrong wrong 1.6.37.

updated to latest master again (jtm1).

This particular witness has been producing blocks at the wrong time this whole time and fortunately helped us identify a bug that we fixed with a hard fork that took effect and is now generating these error messages.

@bytemaster let me know if I should update 1.6.37 now or if you need  it for debugging

[Thom]

The accuracy of each individual computers clock can be off by up to 300 ms.   It just means that your local clock is ahead of the other peer by 23 ms plus the network latency in fetching the block.

So there is a margin of error of 300ms in latency numbers?

That makes it pretty tough to get an accurate picture. I thought ntp would take care of that, not so?

[rnglab]

bitshares-argentina  can you please let me know if you have changed your software in any way because it appears your node is consistently producing blocks even though you are not in the set of active witnesses.

Everyone else, please update your witness to the latest master before block 58500  (about 4 hours).

Hi dan, I didn't change anything. Neither played with uncommon settings as far as I remember . 

Running from master branch with last commit db84a492b9a2cf290f92a3987b59c11808138d56

How can I help debugging?

[jakub]

bitshares-argentina  can you please let me know if you have changed your software in any way because it appears your node is consistently producing blocks even though you are not in the set of active witnesses.

BM, does this strange event have an explanation now or is it still unclear what happened?

[pc]

pmc updated to latest master.

[bytemaster]

are we able to set up a bunch of witnesses with 36 cores (with > 10Mbit/s bandwidth) and test out higher TPS? We can pay $100 for a month for say 17 witnesses for a cost of $1700 to prove to the world we can do 100k TPS on a stable testnet.

It isn't just a matter of getting high end servers, we need to actually change the P2P protocol before we can hope to achieve those speeds.

[jsidhu]

are we able to set up a bunch of witnesses with 36 cores (with > 10Mbit/s bandwidth) and test out higher TPS? We can pay $100 for a month for say 17 witnesses for a cost of $1700 to prove to the world we can do 100k TPS on a stable testnet.

[bytemaster]

delegate.verbaltech witness crashed around 12:25 CST, 30 minutes or so after I started it. I just restarted it. Noticed several black swan events and witness producing blocks at the wrong time:

   55.24%   32000 of 57929                                                                 [445/1942]
   58.6925%   34000 of 57929   
1777187ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 759.92759999999998399  0.00131591483188662
   Settle Price:              0.00414700000000000  241.13817217265491877
   Max:                       0.00414700000000000   241.13817217265491877

   62.145%   36000 of 57929   
1779453ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 60900.10198737338214414  0.00001642033374932
   Settle Price:              0.00003138000000000  31867.43148502230542363
   Max:                       0.00003138000000000   31867.43148502230542363

   65.5975%   38000 of 57929   
   69.05%   40000 of 57929   
   72.5025%   42000 of 57929   
   75.955%   44000 of 57929   
   79.4076%   46000 of 57929   
   82.8601%   48000 of 57929   
   86.3126%   50000 of 57929   
1824293ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 69.44539226603158966  0.01439980346239816
   Settle Price:              0.03222000000000000  31.03662321539416524
   Max:                       0.03222000000000000   31.03662321539416524

Looks pretty stable now tho, no problems since:

2004762ms th_a       application.cpp:394           handle_block         ] Got block: #59514 time: 201
5-10-07T18:33:24 latency: 768 ms from: delegate.btsnow  irreversible: 59492 (-22)

Also noticed this - how can this be correct?:

5-10-07T18:40:51 latency: -23 ms from: bitcube  irreversible: 59631 (-26)
2454409ms th_a       application.cpp:394           handle_block         ] Got block: #59658 time: 201

The accuracy of each individual computers clock can be off by up to 300 ms.   It just means that your local clock is ahead of the other peer by 23 ms plus the network latency in fetching the block.

[bytemaster]

BM, I think there are now 3 witnesses waiting to be voted in:

bitshares-argentina
triox-delegate
pmc

Voted.   Any others?

[Thom]

delegate.verbaltech witness crashed around 12:25 CST, 30 minutes or so after I started it. 98 missed blocks then, 154 now after I just restarted it. Noticed several black swan events and witness producing blocks at the wrong time:

   55.24%   32000 of 57929                                                                 [445/1942]
   58.6925%   34000 of 57929   
1777187ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 759.92759999999998399  0.00131591483188662
   Settle Price:              0.00414700000000000  241.13817217265491877
   Max:                       0.00414700000000000   241.13817217265491877

   62.145%   36000 of 57929   
1779453ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 60900.10198737338214414  0.00001642033374932
   Settle Price:              0.00003138000000000  31867.43148502230542363
   Max:                       0.00003138000000000   31867.43148502230542363

   65.5975%   38000 of 57929   
   69.05%   40000 of 57929   
   72.5025%   42000 of 57929   
   75.955%   44000 of 57929   
   79.4076%   46000 of 57929   
   82.8601%   48000 of 57929   
   86.3126%   50000 of 57929   
1824293ms th_a       db_update.cpp:241             check_for_blackswan  ] Black Swan detected:
   Least collateralized call: 69.44539226603158966  0.01439980346239816
   Settle Price:              0.03222000000000000  31.03662321539416524
   Max:                       0.03222000000000000   31.03662321539416524

Looks pretty stable now tho, no problems since:

2004762ms th_a       application.cpp:394           handle_block         ] Got block: #59514 time: 201
5-10-07T18:33:24 latency: 768 ms from: delegate.btsnow  irreversible: 59492 (-22)

Also noticed this - how can this be correct?:

5-10-07T18:40:51 latency: -23 ms from: bitcube  irreversible: 59631 (-26)
2454409ms th_a       application.cpp:394           handle_block         ] Got block: #59658 time: 201

Latency times are all over the place: -22ms from bitcube, 110ms from clayop, 700ms from init6, 762ms from bitshares-argentina. They do seem to corelate with being in Singnapore tho.

[triox]

Updated.

Is it still the case that "total_votes" shows zero until the candidate is voted in?

[bytemaster]

I am getting this sometimes

Code: [Select]

3033114ms th_a       db_block.cpp:191              _push_block          ] Failed to push new block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block
3033116ms th_a       application.cpp:425           handle_block         ] Error when pushing block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block

    {"new_block":{"previous":"0000e55de39c07283d1779c89018c18206bfa9f2","timestamp":"2015-10-07T17:50:33","witness":"1.6.37","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f19b73fc82aa7519e28f34b1f8e10f63da27365c8e5699fd9f77c0ee1f4c4b02841560af821e3ec8e71f72264934140c7fb2cdd78e0f91920edc7b8cba9c33cfb","transactions":[]}}
    th_a  db_block.cpp:197 _push_block


I see the same. Perhaps something wrong wrong 1.6.37.

updated to latest master again (jtm1).

This particular witness has been producing blocks at the wrong time this whole time and fortunately helped us identify a bug that we fixed with a hard fork that took effect and is now generating these error messages.

[jtme]

I am getting this sometimes

Code: [Select]

3033114ms th_a       db_block.cpp:191              _push_block          ] Failed to push new block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block
3033116ms th_a       application.cpp:425           handle_block         ] Error when pushing block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block

    {"new_block":{"previous":"0000e55de39c07283d1779c89018c18206bfa9f2","timestamp":"2015-10-07T17:50:33","witness":"1.6.37","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f19b73fc82aa7519e28f34b1f8e10f63da27365c8e5699fd9f77c0ee1f4c4b02841560af821e3ec8e71f72264934140c7fb2cdd78e0f91920edc7b8cba9c33cfb","transactions":[]}}
    th_a  db_block.cpp:197 _push_block


I see the same. Perhaps something wrong wrong 1.6.37.

updated to latest master again (jtm1).

[Bhuz]

I am getting this sometimes

Code: [Select]

3033114ms th_a       db_block.cpp:191              _push_block          ] Failed to push new block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block
3033116ms th_a       application.cpp:425           handle_block         ] Error when pushing block:
10 assert_exception: Assert Exception
next_block.witness == scheduled_witness: Witness produced block at wrong time
    {"block witness":"1.6.37","scheduled":"1.6.24","slot_num":1}
    th_a  db_block.cpp:646 validate_block_header

    {"next_block.block_num()":58718}
    th_a  db_block.cpp:511 _apply_block

    {"new_block":{"previous":"0000e55de39c07283d1779c89018c18206bfa9f2","timestamp":"2015-10-07T17:50:33","witness":"1.6.37","transaction_merkle_root":"0000000000000000000000000000000000000000","extensions":[],"witness_signature":"1f19b73fc82aa7519e28f34b1f8e10f63da27365c8e5699fd9f77c0ee1f4c4b02841560af821e3ec8e71f72264934140c7fb2cdd78e0f91920edc7b8cba9c33cfb","transactions":[]}}
    th_a  db_block.cpp:197 _push_block


[CalabiYau]

updated (observer) witness_node to latest.