Missing random blocks

[spartako]

Today I missed two random blocks for latency problem:

Log:

Code: [Select]

a       application.cpp:496           handle_block         ] Got block: #1001618 time: 2015-11-17T15:57:39 latency: 18138 ms from: elmato  irreversible: 1001599 (-19)
3477140ms th_a       application.cpp:496           handle_block         ] Got block: #1001618 time: 2015-11-17T15:57:39 latency: 18139 ms from: elmato  irreversible: 1001600 (-18)
3477140ms th_a       application.cpp:496           handle_block         ] Got block: #1001618 time: 2015-11-17T15:57:39 latency: 18139 ms from: elmato  irreversible: 1001600 (-18)
3477140ms th_a       application.cpp:496           handle_block         ] Got block: #1001619 time: 2015-11-17T15:57:45 latency: 12139 ms from: delegate.taolje  irreversible: 1001600 (-1
9)
3477141ms th_a       application.cpp:496           handle_block         ] Got block: #1001619 time: 2015-11-17T15:57:45 latency: 12140 ms from: delegate.taolje  irreversible: 1001601 (-1
8)
3477141ms th_a       application.cpp:496           handle_block         ] Got block: #1001619 time: 2015-11-17T15:57:45 latency: 12140 ms from: delegate.taolje  irreversible: 1001601 (-1
8)
3477141ms th_a       application.cpp:496           handle_block         ] Got block: #1001620 time: 2015-11-17T15:57:51 latency: 6141 ms from: triox-delegate  irreversible: 1001601 (-19)
3477143ms th_a       application.cpp:496           handle_block         ] Got block: #1001620 time: 2015-11-17T15:57:51 latency: 6142 ms from: triox-delegate  irreversible: 1001601 (-19)
3477214ms th_a       application.cpp:496           handle_block         ] Got block: #1001622 time: 2015-11-17T15:57:57 latency: 213 ms from: delegate.taolje  irreversible: 1001601 (-21)
3477215ms th_a       fork_database.cpp:60          push_block           ] Pushing block to fork database that failed to link: 000f48968aece4333ba06889b004a5c1e16bc19d, 1001622
3477215ms th_a       fork_database.cpp:61          push_block           ] Head: 1001620, 000f4894bed1f06f2145862679ab61628039d9da
3477216ms th_a       application.cpp:524           handle_block         ] Error when pushing block:
3080000 unlinkable_block_exception: unlinkable block
block does not link to known chain
    {}
    th_a  fork_database.cpp:81 _push_block

    {"new_block":{"previous":"000f4895eaf2f604f7b828b29678fb18b9a84429","timestamp":"2015-11-17T15:57:57","witness":"1.6.38","transaction_merkle_root":"0000000000000000000000000000000000
000000","extensions":[],"witness_signature":"1f33da357bd9e33d9644d277974f84413ac9335f54cf337f9587749224d876688a38140ac2390d5bebd56f41698771143ecdd7e417d872b9b31e18a605cb0d1cfd","transact
ions":[]}}
    th_a  db_block.cpp:200 _push_block


[xeroc]

If this is happening regularly for you but not for anybody else I'd say this is a network problem on your side. So far I can't see that we have a general block propagation issue.

And depending on where your machine is located, you may not be able to do ANYTHING against it.
Essentially, it breaks down to how many "hops" does a TCP packet need to take to get to your machine.
In the end, the best spot for witness nodes would be *very close* to the internet's backbone so that you can reach most countries with 2 to 3 hops.

[pc]

If your clock is slightly early this would increase the problem, but it doesn't explain the 3s latency.

I am using NTP, even so the clock could still be slightly early... but as you already said, not so much to have problem with 3sec block time...
So could it be a problem of blocks propagation?

If this is happening regularly for you but not for anybody else I'd say this is a network problem on your side. So far I can't see that we have a general block propagation issue.

[Bhuz]

If your clock is slightly early this would increase the problem, but it doesn't explain the 3s latency.

I am using NTP, even so the clock could still be slightly early... but as you already said, not so much to have problem with 3sec block time...
So could it be a problem of blocks propagation?

[pc]

So, I generated the #938170 thinking that in.abit missed his block, but doing so I missed to generate the block #938171 that shoulded link to his #938170 ?

Yes.
The thing is, your node couldn't really do anything else, because it was time to generate a block and it hadn't seen in.abit's yet.

Could this be caused by a bad blocks propagation?
Or is this just very bad luck on my witness that encounterd some strange network freeze (?!) just in those seconds in wich I shoulded sign a block?
Because my latency is good, 200ms average with the highest on 500/600 (3ish witnesses from Asia)

The average doesn't help you here. Fact is, your node received in.abit's block 3 seconds after it was signed.
If your clock is slightly early this would increase the problem, but it doesn't explain the 3s latency.

[Bhuz]

Judging from the log timestamps, you produce block #938170 6 seconds after receiving #938169. By that time you haven't seen in.abit's #938170 yet and assume that he has missed a block.
Unfortunately for you, bue builds #938171 based on in.abit's #938170, orphaning yours. After receiving these two your node recognizes the new longer fork and switches to it. Everything works as designed.

Same in the other log excerpt.

What's killing you is the extreme latency.

So, I generated the #938170 thinking that in.abit missed his block, but doing so I missed to generate the block #938171 that shoulded link to his #938170 ?
Could this be caused by a bad blocks propagation?
Or is this just very bad luck on my witness that encounterd some strange network freeze (?!) just in those seconds in wich I shoulded sign a block?
Because my latency is good, 200ms average with the highest on 500/600 (3ish witnesses from Asia)

[pc]

@bytemaster Could you please explain what is happening in the following situation?

Code: [Select]

3141381ms th_a       application.cpp:496           handle_block         ] Got block: #938169 time: 2015-11-15T10:52:21 latency: 383 ms from: fox  irreversible: 938140 (-29)
3146998ms th_a       witness.cpp:185               block_production_loo ] Generated block #938170 with timestamp 2015-11-15T10:52:27 at time 2015-11-15T10:52:27
3147201ms th_a       application.cpp:496           handle_block         ] Got block: #938170 time: 2015-11-15T10:52:24 latency: 3203 ms from: in.abit  irreversible: 938146 (-24)
3150236ms th_a       application.cpp:496           handle_block         ] Got block: #938171 time: 2015-11-15T10:52:30 latency: 238 ms from: bue  irreversible: 938146 (-25)
3150236ms th_a       db_block.cpp:137              _push_block          ] Switching to fork: 000e50bb5ba87838b334fa8f7e330fa4fa00113c
3150237ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 938170 000e50ba27bba65c3f756856e880e72553c061c9
3150238ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 938171 000e50bb5ba87838b334fa8f7e330fa4fa00113c
3153138ms th_a       application.cpp:496           handle_block         ] Got block: #938172 time: 2015-11-15T10:52:33 latency: 140 ms from: maqifrnswa  irreversible: 938146 (-26)

2-my witness is called to generate a block consequently a missed block by another wittness that, with 3sec delay shows up and replaces my block, making me the one who missed a block(?!)

Judging from the log timestamps, you produce block #938170 6 seconds after receiving #938169. By that time you haven't seen in.abit's #938170 yet and assume that he has missed a block.
Unfortunately for you, bue builds #938171 based on in.abit's #938170, orphaning yours. After receiving these two your node recognizes the new longer fork and switches to it. Everything works as designed.

Same in the other log excerpt.

What's killing you is the extreme latency.

[Bhuz]

@bytemaster Could you please explain what is happening in the following situation?

Code: [Select]

3141381ms th_a       application.cpp:496           handle_block         ] Got block: #938169 time: 2015-11-15T10:52:21 latency: 383 ms from: fox  irreversible: 938140 (-29)
3146998ms th_a       witness.cpp:185               block_production_loo ] Generated block #938170 with timestamp 2015-11-15T10:52:27 at time 2015-11-15T10:52:27
3147201ms th_a       application.cpp:496           handle_block         ] Got block: #938170 time: 2015-11-15T10:52:24 latency: 3203 ms from: in.abit  irreversible: 938146 (-24)
3150236ms th_a       application.cpp:496           handle_block         ] Got block: #938171 time: 2015-11-15T10:52:30 latency: 238 ms from: bue  irreversible: 938146 (-25)
3150236ms th_a       db_block.cpp:137              _push_block          ] Switching to fork: 000e50bb5ba87838b334fa8f7e330fa4fa00113c
3150237ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 938170 000e50ba27bba65c3f756856e880e72553c061c9
3150238ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 938171 000e50bb5ba87838b334fa8f7e330fa4fa00113c
3153138ms th_a       application.cpp:496           handle_block         ] Got block: #938172 time: 2015-11-15T10:52:33 latency: 140 ms from: maqifrnswa  irreversible: 938146 (-26)

And same here

Code: [Select]

1152088ms th_a       application.cpp:496           handle_block         ] Got block: #968534 time: 2015-11-16T12:19:12 latency: 88 ms from: rnglab  irreversible: 968513 (-21)
1158000ms th_a       witness.cpp:185               block_production_loo ] Generated block #968535 with timestamp 2015-11-16T12:19:18 at time 2015-11-16T12:19:18
1158248ms th_a       application.cpp:496           handle_block         ] Got block: #968535 time: 2015-11-16T12:19:15 latency: 3248 ms from: dragonball  irreversible: 968515 (-20)
1161624ms th_a       application.cpp:496           handle_block         ] Got block: #968536 time: 2015-11-16T12:19:21 latency: 624 ms from: fox  irreversible: 968515 (-21)
1161624ms th_a       db_block.cpp:137              _push_block          ] Switching to fork: 000ec7587fdba930c1d08a4c9918394160eceb62
1161624ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 968535 000ec757516cb356622a848c9bce44ed535a55b7
1161625ms th_a       db_block.cpp:147              _push_block          ] pushing blocks from fork 968536 000ec7587fdba930c1d08a4c9918394160eceb62
1164150ms th_a       application.cpp:496           handle_block         ] Got block: #968537 time: 2015-11-16T12:19:24 latency: 150 ms from: delegate-1.lafona  irreversible: 968516 (-21)

I can't figure out if:
1-my witness node is generating the block with 3sec delay (still there is no message about "missing block because replaying after 500ms" etc), making me miss the block and calling another witness to sign it for me.
2-my witness is called to generate a block consequently a missed block by another wittness that, with 3sec delay shows up and replaces my block, making me the one who missed a block(?!)
3-some block propagation problem

Could you clarify this? Thanks