Failure on block creation (invalid state against the network blockchain) #1379

Scitz0 · 2019-12-16T21:56:41Z

Describe the bug
Got elected to create some blocks but on two occations it failed with reason:
"Not computing this schedule because of invalid state against the network blockchain"
See below for full output of the failed blocks.

Mandatory Information

jcli --full-version output;
jcli 0.8.2 (HEAD-fe327f9, release, linux [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]
jormungandr --full-version output;
jormungandr 0.8.2 (HEAD-fe327f9, release, linux [x86_64]) - [rustc 1.39.0 (4560ea788 2019-11-04)]

To Reproduce
Unknown

Expected behavior
Successful block creation

Additional context
server synced with ntp deamon so should be in sync

Logs indicate a time issue though:
Dec 16 21:58:29.000 INFO Leader event started, event_remaining_time: 1s 999ms 688us 267ns, event_end: 2019-12-16T20:58:31+00:00, event_start: 2019-12-16T20:58:29+00:00, event_date: 3.3146, leader_id: 1, task: leadership
Dec 16 21:58:29.000 WARN It appears the node is running a bit behind schedule, system time might be off?, event_remaining_time: 1s 999ms 688us 267ns, event_end: 2019-12-16T20:58:31+00:00, event_start: 2019-12-16T20:58:29+00:00, event_date: 3.3146, leader_id: 1, task: leadership
Dec 16 21:58:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier

Dec 16 22:16:55.000 INFO Leader event started, event_remaining_time: 1s 999ms 402us 235ns, event_end: 2019-12-16T21:16:57+00:00, event_start: 2019-12-16T21:16:55+00:00, event_date: 3.3699, leader_id: 1, task: leadership
Dec 16 22:16:55.000 WARN It appears the node is running a bit behind schedule, system time might be off?, event_remaining_time: 1s 999ms 402us 235ns, event_end: 2019-12-16T21:16:57+00:00, event_start: 2019-12-16T21:16:55+00:00, event_date: 3.3699, leader_id: 1, task: leadership

Searching through todays logs I can see the ERROR a couple of times during a 1,5h period.
Dec 16 20:52:29.997 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:53:29.998 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:54:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:55:29.999 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:56:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:55:29.998 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:56:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:57:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:58:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:15:29.998 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:16:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:17:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:18:29.996 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier

created_at_time: "2019-12-16T19:13:47.169638924+00:00"
enclave_leader_id: 1
finished_at_time: "2019-12-16T20:58:29.000338233+00:00"
scheduled_at_date: "3.3146"
scheduled_at_time: "2019-12-16T20:58:29+00:00"
status:
Rejected:
reason: Not computing this schedule because of invalid state against the network blockchain
wake_at_time: "2019-12-16T20:58:29.000296094+00:00"
created_at_time: "2019-12-16T19:13:47.169643472+00:00"
enclave_leader_id: 1
finished_at_time: "2019-12-16T21:16:55.000620608+00:00"
scheduled_at_date: "3.3699"
scheduled_at_time: "2019-12-16T21:16:55+00:00"
status:
Rejected:
reason: Not computing this schedule because of invalid state against the network blockchain
wake_at_time: "2019-12-16T21:16:55.000581795+00:00"

The text was updated successfully, but these errors were encountered:

JamesRobertKelley · 2019-12-16T22:25:47Z

I'm seeing the stuck_notifier error as well. My system time seems to be correct.

frugalpool · 2019-12-16T22:50:56Z

Mon 16 Dec 2019 10:47:44 PM UTC
root@frugalmaster:~/frugalpool# cat logs/node.out | grep ERRO
Dec 16 19:52:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 19:53:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 19:54:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 19:55:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 19:56:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:54:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:55:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:56:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 20:57:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:14:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:15:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:16:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 21:17:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:02:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:03:42.040 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:04:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:05:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:06:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:07:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:08:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:09:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:10:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:11:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:12:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:21:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:22:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:23:42.038 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier
Dec 16 22:24:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier

Scitz0 · 2019-12-16T22:54:01Z

Mon 16 Dec 2019 10:47:44 PM UTC
root@frugalmaster:~/frugalpool# cat logs/node.out | grep ERRO
Dec 16 19:52:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier

You also see failed block creations?

frugalpool · 2019-12-16T22:54:31Z

root@frugalmaster:~/frugalpool# ntpstat
synchronised to NTP server (129.250.35.250) at stratum 3
time correct to within 51 ms
polling server every 1024 s

frugalpool · 2019-12-16T22:56:20Z

created_at_time: "2019-12-16T19:13:47.466092084+00:00"
enclave_leader_id: 1
finished_at_time: "2019-12-16T22:12:49.000392194+00:00"
scheduled_at_date: "3.5376"
scheduled_at_time: "2019-12-16T22:12:49+00:00"
status:
Rejected:
reason: Not computing this schedule because of invalid state against the network blockchain
wake_at_time: "2019-12-16T22:12:49.000253868+00:00"
created_at_time: "2019-12-16T19:13:47.466091202+00:00"
enclave_leader_id: 1
finished_at_time: "2019-12-16T22:08:07.000481334+00:00"
scheduled_at_date: "3.5235"
scheduled_at_time: "2019-12-16T22:08:07+00:00"
status:
Rejected:
reason: Not computing this schedule because of invalid state against the network blockchain
wake_at_time: "2019-12-16T22:08:07.000351242+00:00"

frugalpool · 2019-12-16T22:57:48Z

Mon 16 Dec 2019 10:47:44 PM UTC
root@frugalmaster:~/frugalpool# cat logs/node.out | grep ERRO
Dec 16 19:52:42.037 ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier

You also see failed block creations?

yes, two failed blocks

frugalpool · 2019-12-17T02:31:14Z

I have three different machines running on ITN1 and they each detect the most recent anomaly at the same time +/- 59 sec via cron.

Tue 17 Dec 2019 02:14:01 AM UTC
Tue 17 Dec 2019 02:16:01 AM UTC

I have another machine that is configured identically but running 0.8.2 Nightly without the anomalous behavior.

reliablestaking · 2019-12-17T02:44:00Z

Saw a similar issue

- created_at_time: "2019-12-16T19:13:49.365643356+00:00"
  enclave_leader_id: 1
  finished_at_time: "2019-12-17T02:25:45.001889446+00:00"
  scheduled_at_date: "3.12964"
  scheduled_at_time: "2019-12-17T02:25:45+00:00"
  status:
    Rejected:
      reason: Not computing this schedule because of invalid state against the network blockchain
  wake_at_time: "2019-12-17T02:25:45.001821633+00:00"

- created_at_time: "2019-12-16T19:13:49.365640546+00:00"
  enclave_leader_id: 1
  finished_at_time: "2019-12-17T02:25:43.001542185+00:00"
  scheduled_at_date: "3.12963"
  scheduled_at_time: "2019-12-17T02:25:43+00:00"
  status:
    Rejected:
      reason: Not computing this schedule because of invalid state against the network blockchain
  wake_at_time: "2019-12-17T02:25:43.001473785+00:00"

frugalpool · 2019-12-17T06:25:03Z

This seems to remedy the situation...

"max_connections": 50,

frugalpool · 2019-12-17T06:42:20Z

well not long after I said the max_connections solved the problem the node stopped making progress so that's not the root cause

Scitz0 · 2019-12-17T08:53:56Z

55% of epoch 3 done and I have 21 successfully created blocks, 6 failed of whitch 5 failed beause of error reported in this issue and one due to race condition I assume.

I wont fill this github issue with more error logs but since yesterday morning (GMT+1) at 20:52 node has logged 99 of these:
Dec 16 20:52:29.997 ERRO cannot compute the time passed since the last block: second time provided was later than self, task:
stuck_notifier

I made some changes to ntp deamon but doesn't seem to change the situation.

Adding current node-config.yaml to issue:

log:
  - output: stderr
    format: plain
    level: info
p2p:
  listen_address: "/ip4/0.0.0.0/tcp/3333"
  public_address: "/ip4/xxx.xxx.xxx.xxx/tcp/3333"
  topics_of_interest:
    blocks: high
    messages: high
  max_connections: 256
  trusted_peers:
  - address: "/ip4/52.9.132.248/tcp/3000"
    id: 671a9e7a5c739532668511bea823f0f5c5557c99b813456c
  - address: "/ip4/52.8.15.52/tcp/3000"
    id: 18bf81a75e5b15a49b843a66f61602e14d4261fb5595b5f5
  - address: "/ip4/13.114.196.228/tcp/3000"
    id: 7e1020c2e2107a849a8353876d047085f475c9bc646e42e9
  - address: "/ip4/13.112.181.42/tcp/3000"
    id: 52762c49a84699d43c96fdfe6de18079fb2512077d6aa5bc
  - address: "/ip4/3.125.75.156/tcp/3000"
    id: 22fb117f9f72f38b21bca5c0f069766c0d4327925d967791
  - address: "/ip4/52.28.91.178/tcp/3000"
    id: 23b3ca09c644fe8098f64c24d75d9f79c8e058642e63a28c
  - address: "/ip4/3.124.116.145/tcp/3000"
    id: 99cb10f53185fbef110472d45a36082905ee12df8a049b74
rest:
  listen: 0.0.0.0:3101
storage: "/home/cardano/jormungandr/storage/testnet"
mempool:
  #pool_max_entries: 100000
  fragment_ttl: 15m
  #log_max_entries: 100000
  log_ttl: 6h
  garbage_collection_interval: 15m
leadership:
  log_ttl: 24h
  garbage_collection_interval: 6h

frugalpool · 2019-12-17T20:16:37Z

I've had some success mitigating this problem by assigning different ports to the listen address and public address.

lordwotton29 · 2019-12-18T07:54:44Z

I had the same problem in epoch 3, lost 4-5 blocks due to invalid state against the network blockchain

JSCSJSCS · 2019-12-19T00:48:38Z

Just wanted to jump in with a me too. I have not seen this error before and have been testing versions since the 0.6's. I too see many stuck notifier msg's in the logs and of course they start just before it is my pools time to set the block. I am using Windows and the max_connections config setting has not effect on the OS where it is set to 200 and I am currently at 550.

adamite-pool · 2019-12-19T12:52:05Z

I had the same issue, I was scheduled to produce 5.31066, I checked my node before the time and that what I saw

$ jcli rest v0 node stats get --host "http://127.0.0.1:3100/api"
---
blockRecvCnt: 0
lastBlockContentSize: 872
lastBlockDate: "5.31079"
lastBlockFees: 2300000
lastBlockHash: c379b87e305bf3d5a2fc26b30b1b7ad1975ab1ddc2696bd47e18404438319fe7
lastBlockHeight: "20174"
lastBlockSum: 259230965428
lastBlockTime: ~
lastBlockTx: 3
state: Running
txRecvCnt: 2
uptime: 36
version: jormungandr 0.8.3-8f276c0
$ jcli rest v0 leaders logs get -h http://127.0.0.1:3100/api
---
- created_at_time: "2019-12-19T12:27:35.048584090+00:00"
  enclave_leader_id: 1
  finished_at_time: ~
  scheduled_at_date: "5.31066"
  scheduled_at_time: "2019-12-19T12:29:09+00:00"
  status: Pending
  wake_at_time: ~

My block is still pending because it was too early to produce it, however, 5.31079 was already in the explorer, so it is not a fork as far as I can tell. My block got rejected with the same message as everyone in this thread

Jonne33 · 2019-12-19T13:20:04Z

Same issue here from time to time on 0.8.3:

In the leader log:

created_at_time: "2019-12-19T11:44:59.466101540+00:00"
enclave_leader_id: 1
finished_at_time: "2019-12-19T12:29:11.001264519+00:00"
scheduled_at_date: "5.31067"
scheduled_at_time: "2019-12-19T12:29:11+00:00"
status:
Rejected:
reason: Not computing this schedule because of invalid state against the network blockchain
wake_at_time: "2019-12-19T12:29:11.001083035+00:00"

In the node log:

Dec 19 13:29:11.001 INFO Leader event started, event_remaining_time: 1s 998ms 821us 819ns, event_end: 2019-12-19T12:29:13+00:00, event_start: 2019-12-19T12:29:11+00:00, event_date: 5.31067, leader_id: 1, task: leadership

Dec 19 13:29:11.001 WARN It appears the node is running a bit behind schedule, system time might be off?, event_remaining_time: 1s 998ms 821us 819ns, event_end: 2019-12-19T12:29:13+00:00, event_start: 2019-12-19T12:29:11+00:00, event_date: 5.31067, leader_id: 1, task: leadership.

Any recommendations? Thank you.

rinor · 2020-01-06T21:43:12Z

is this still relevant/happening in v0.8.5?

Jonne33 · 2020-01-06T22:16:30Z

Haven't faced it with 0.8.5

Scitz0 · 2020-01-06T22:22:29Z

To few blocks for my pool to tell if it's still a problem 😪 Den mån 6 jan. 2020 16:16Jonne33 <[email protected]> skrev:

…

Haven't faced it with 0.8.5 — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#1379?email_source=notifications&email_token=ADZKXDPJTDUENJWKFSHFA5LQ4OUT7A5CNFSM4J3R6T3KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIG7IDY#issuecomment-571339791>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADZKXDKXLC3CJSY56NGK3Q3Q4OUT7ANCNFSM4J3R6T3A> .

rinor · 2020-01-06T22:41:29Z

Thank you for the feedback.

Regarding Not computing this schedule because of invalid state against the network blockchain there are some changes made that should prevent this from happening in v0.8.5, so if the block is set in the future (from the local PoV) it won't be considered just yet as a prefered candidate for the tip of the blockchain.

The same applies to ERRO cannot compute the time passed since the last block: second time provided was later than self, task: stuck_notifier. Check also #1404 (comment)

@Scitz0 sorry about your block amount.

Will close this one for now, but please feel free to reopen/comment in case you encounter it again. Thank you.

BitcoinMicroPaymentNetwork · 2020-01-31T18:16:17Z

I get it in 0.8.9 version
Jan 31 23:10:20.596 WARN It appears the node is running a bit behind schedule, system time might be off?, event_remaining_time: 403ms 514us, event_end: 2020-01-31T17:40:21+00:00, event_start: 2020-01-31T17:40:19+00:00, event_date: 48.40401, leader_id: 1, task: leadership

mzabaluev · 2020-01-31T18:38:07Z

Let's reopen this rather than splitting the discussion with #1689

rinor closed this as completed Jan 6, 2020

rinor mentioned this issue Jan 6, 2020

ERRO cannot compute the time passed #1404

Closed

mzabaluev reopened this Jan 31, 2020

mzabaluev mentioned this issue Jan 31, 2020

Not computing this schedule because of invalid state against the network blockchain #1689

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Failure on block creation (invalid state against the network blockchain) #1379

Failure on block creation (invalid state against the network blockchain) #1379

Scitz0 commented Dec 16, 2019 •

edited

Loading

JamesRobertKelley commented Dec 16, 2019

frugalpool commented Dec 16, 2019

Scitz0 commented Dec 16, 2019 •

edited

Loading

frugalpool commented Dec 16, 2019

frugalpool commented Dec 16, 2019

frugalpool commented Dec 16, 2019

frugalpool commented Dec 17, 2019

reliablestaking commented Dec 17, 2019

frugalpool commented Dec 17, 2019

frugalpool commented Dec 17, 2019

Scitz0 commented Dec 17, 2019 •

edited

Loading

frugalpool commented Dec 17, 2019

lordwotton29 commented Dec 18, 2019

JSCSJSCS commented Dec 19, 2019

adamite-pool commented Dec 19, 2019 •

edited

Loading

Jonne33 commented Dec 19, 2019 •

edited

Loading

rinor commented Jan 6, 2020

Jonne33 commented Jan 6, 2020

Scitz0 commented Jan 6, 2020 via email

rinor commented Jan 6, 2020

BitcoinMicroPaymentNetwork commented Jan 31, 2020

mzabaluev commented Jan 31, 2020

Failure on block creation (invalid state against the network blockchain) #1379

Failure on block creation (invalid state against the network blockchain) #1379

Comments

Scitz0 commented Dec 16, 2019 • edited Loading

JamesRobertKelley commented Dec 16, 2019

frugalpool commented Dec 16, 2019

Scitz0 commented Dec 16, 2019 • edited Loading

frugalpool commented Dec 16, 2019

frugalpool commented Dec 16, 2019

frugalpool commented Dec 16, 2019

frugalpool commented Dec 17, 2019

reliablestaking commented Dec 17, 2019

frugalpool commented Dec 17, 2019

frugalpool commented Dec 17, 2019

Scitz0 commented Dec 17, 2019 • edited Loading

frugalpool commented Dec 17, 2019

lordwotton29 commented Dec 18, 2019

JSCSJSCS commented Dec 19, 2019

adamite-pool commented Dec 19, 2019 • edited Loading

Jonne33 commented Dec 19, 2019 • edited Loading

rinor commented Jan 6, 2020

Jonne33 commented Jan 6, 2020

Scitz0 commented Jan 6, 2020 via email

rinor commented Jan 6, 2020

BitcoinMicroPaymentNetwork commented Jan 31, 2020

mzabaluev commented Jan 31, 2020

Scitz0 commented Dec 16, 2019 •

edited

Loading

Scitz0 commented Dec 16, 2019 •

edited

Loading

Scitz0 commented Dec 17, 2019 •

edited

Loading

adamite-pool commented Dec 19, 2019 •

edited

Loading

Jonne33 commented Dec 19, 2019 •

edited

Loading