Jormungandr: Multiple "cannot process network headers, reason: deadline has elapsed, task: block" errors

Created on 20 Dec 2019  路  18Comments  路  Source: input-output-hk/jormungandr

Describe the bug
Multiple errors

cannot process network headers, reason: deadline has elapsed, task: block

happening every minute/few minutes.

Example log output

--
Dec 20 11:16:54.665 INFO disconnecting client, node_id: 51cd865faa86387069afd6539137e7da4dc051b1d8a32f70, peer_addr: 77.168.127.192:3000, task: network
Dec 20 11:16:54.684 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: ff738164013735cc5cfa540644e90e7fc4cb8f3a69f8592e, peer_addr: 207.237.205.137:3100, task: network
Dec 20 11:16:54.887 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:16:54.894 INFO peer node ID differs from the expected a538c7ec3143d95e81d80e53b06cfcbaa99040db7d38f49f, node_id: 9776b8eccc91245744d039d3a82e97c6651162421722894e, peer_addr: 62.151.178.94:3000, task: network
Dec 20 11:16:54.963 INFO connecting to peer, node_id: 04f1782b84e0fda00143db199487fbaff8fdd7c23d1091a0, peer_addr: 173.249.43.58:3000, task: network
--
Dec 20 11:18:18.086 INFO disconnecting client, node_id: 72b5a4086612d12c063d77c743765485629a542d010a9006, peer_addr: 54.154.193.39:3000, task: network
Dec 20 11:18:18.220 INFO disconnecting client, node_id: 234588b3165ec62391137ceaeca3dc0910c5620a9cbd30fa, peer_addr: 50.39.165.123:3001, task: network
Dec 20 11:18:18.248 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:18:18.250 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:18:18.597 INFO received block announcement, hash: 23964dc4dfd6012a4747eccacfbddbf43fb8470d82a491a6bf0ac42f87f5a9a9, direction: in, stream: block_events, node_id: 408a43baf4c562338d15b9f72adb949b5c6cfc1ff8115744, peer_addr: 89.162.89.137:9009, task: network
Dec 20 11:18:18.597 INFO received block announcement from network, from_node_id: 408a43baf4c562338d15b9f72adb949b5c6cfc1ff8115744, date: 6.27946, parent: 1d42266650122f632fca534af3fa4bb4e5ec3a99cd1f81c60f18edf8685cf00d, hash: 23964dc4dfd6012a4747eccacfbddbf43fb8470d82a491a6bf0ac42f87f5a9a9, task: block
Dec 20 11:18:18.598 INFO receiving header stream from network, task: block
Dec 20 11:18:18.701 INFO failed to connect to peer, reason: No route to host (os error 113), node_id: b51dfd2fb84f2e477d693e166c688871a17b4e0d9c65a944, peer_addr: 46.183.114.176:3000, task: network
Dec 20 11:18:18.747 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:18:18.753 INFO peer node ID differs from the expected 2fd15a308ccc65e7a062eb68130181d2861e8af1515db882, node_id: 05b14771571b24e2d87e89649b8e5ed8cd9e5cca311a8435, peer_addr: 138.68.62.183:3000, task: network
Dec 20 11:18:18.764 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: a9427741277d0f6b200ff9fc5d5201cc1dd7e929aec6d377, peer_addr: 207.237.205.137:3100, task: network
--
Dec 20 11:20:18.191 INFO disconnecting client, node_id: 2a7a163ea3bcc2455b42d701d1818086513ce88f7acc645a, peer_addr: 178.128.110.133:3000, task: network
Dec 20 11:20:18.256 INFO peer node ID differs from the expected 2b3ef5b7134bb6f91c5ae02244122d68d1eee560ce100d61, node_id: f1da0885b10b0f73f7fc505b4839736ec0135039512fb1f1, peer_addr: 98.151.82.186:3000, task: network
Dec 20 11:20:18.607 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:20:19.234 INFO receiving block stream from network, task: block
Dec 20 11:20:19.443 INFO response stream failed, reason: not found, request: GetBlocks, node_id: f1da0885b10b0f73f7fc505b4839736ec0135039512fb1f1, peer_addr: 98.151.82.186:3000, task: network
--
Dec 20 11:23:08.861 INFO disconnecting client, node_id: f7948760c892c427ab65fd44d1da4084cbba28b3b0b4bd0f, peer_addr: 49.193.36.88:3000, task: network
Dec 20 11:23:08.879 INFO disconnecting client, node_id: 51433919d76c9d02bc80c0707a7a2503175e925854c31f64, peer_addr: 165.22.119.72:3000, task: network
Dec 20 11:23:11.015 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:23:12.367 INFO response stream failed, reason: the operation was aborted, request: PullHeaders, node_id: 22fb117f9f72f38b21bca5c0f069766c0d4327925d967791, peer_addr: 3.125.75.156:3000, task: network
Dec 20 11:23:13.809 INFO disconnecting client, node_id: 85941f4cd44f7bc4c58bc6fbd1538b48e27ed4b6c436bb5c, peer_addr: 95.179.219.33:3000, task: network
--
Dec 20 11:23:14.695 INFO disconnecting client, node_id: fe4967cfd001f1fe670d1be53d511978236dc2c3c7022b4a, peer_addr: 78.46.191.161:3000, task: network
Dec 20 11:23:15.662 INFO disconnecting client, node_id: b23dedf6ab2acb194d5d4e73bcfd88783ab051cf5aca0972, peer_addr: 89.162.89.137:9003, task: network
Dec 20 11:23:16.451 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:23:17.119 INFO response stream failed, reason: the operation was aborted, request: PullHeaders, node_id: 22fb117f9f72f38b21bca5c0f069766c0d4327925d967791, peer_addr: 3.125.75.156:3000, task: network
Dec 20 11:23:17.471 INFO failed to connect to peer, reason: Connection timed out (os error 110), node_id: e977c1693cd69c7cb3cdc84eb19f78723ea125ae97e6afa5, peer_addr: 14.203.162.172:3000, task: network
--
Dec 20 11:23:50.535 INFO disconnecting client, node_id: fe72da28b9fbac02297bf4a3ccddbd44142f8ce7b7ab9e2a, peer_addr: 14.200.26.39:3100, task: network
Dec 20 11:23:50.557 INFO disconnecting client, node_id: e2b74215830776151436879874d25ca3c9703cc1af8cca1c, peer_addr: 45.76.126.160:3000, task: network
Dec 20 11:23:51.801 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:23:52.667 INFO response stream failed, reason: the operation was aborted, request: PullHeaders, node_id: 22fb117f9f72f38b21bca5c0f069766c0d4327925d967791, peer_addr: 3.125.75.156:3000, task: network
Dec 20 11:23:52.782 INFO peer node ID differs from the expected 38060b25c67f21b587891b1ee5c57e017c0390e0660dc9e3, node_id: 83b6695a594a3d17b3d95d352e4b951cd76f694cba0720e3, peer_addr: 45.77.154.167:3000, task: network
--
Dec 20 11:24:34.288 INFO disconnecting client, node_id: 3e2d6ec5c486a004a0f1dec355e952992e5165c59dbf388f, peer_addr: 45.153.186.221:3100, task: network
Dec 20 11:24:35.239 INFO disconnecting client, node_id: 1690dcfa213a0ee91ee9b008b7d16938ab82ca742ad57371, peer_addr: 89.162.89.137:9004, task: network
Dec 20 11:24:35.948 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 20 11:24:36.452 INFO response stream failed, reason: the operation was aborted, request: PullHeaders, node_id: 22fb117f9f72f38b21bca5c0f069766c0d4327925d967791, peer_addr: 3.125.75.156:3000, task: network
Dec 20 11:24:37.592 INFO connecting to peer, node_id: 7af309f8a6aa3fcd1fbb1dc478b5ec0a4812af70cbf9b876, peer_addr: 3.226.160.142:3000, task: network

Mandatory Information

  1. jcli --full-version output; - jcli 0.8.4 (HEAD-2227eb2, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
  2. jormungandr --full-version output; - jormungandr 0.8.4 (HEAD-2227eb2, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

To Reproduce
Steps to reproduce the behavior:

  1. Config:
log:
  - output: stderr
    level: info
    format: plain
explorer:
  enabled: true
p2p:
  topics_of_interest:
    blocks: high
    messages: high
  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:
  cors:
    allowed_origins:
    - http://localhost:8000
    - http://127.0.0.1:8443
  listen: 127.0.0.1:8443
storage: "/home/lewis/jormungandr/storage/"

Expected behavior
To see less errors.

Additional context

  • I wasn't seeing any of these errors on 0.8.3.
  • The node was started on 0.8.4 at 2019-12-19 21:22:36.288 UTC
  • The errors first started to appear at Dec 20 07:26:02.310 UTC
  • Additional warning started to appear at Dec 19 22:31:47.590 UTC WARN blockchain is not moving up, the last block was 1834 seconds ago, task: stuck_notifier
bug subsys-block Priority - High
Source
picture lewnelson

Most helpful comment

Same for me in 0.8.5.

picture mmahut on 25 Dec 2019
👍6

All 18 comments

Have restarted the node. Will see if it makes any difference over the next few hours.

lewnelson picture lewnelson on 20 Dec 2019

Issue still persists. The only way to resolve is to periodically delete the storage and restart the node

lewnelson picture lewnelson on 21 Dec 2019
👍3

are you seeing this issue with 0.8.5-alph1 or -alpha2 ?

NicolasDP picture NicolasDP on 21 Dec 2019 
jormungandr 0.8.5-alpha2 (HEAD-71d252e, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
jcli 0.8.5-alpha2 (HEAD-71d252e, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

Dec 22 12:02:14.020 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:14.020 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:14.059 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:18.422 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:23.854 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 12:02:24.871 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:26.118 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 12:02:26.669 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:02:26.699 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 12:02:26.898 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network

node gets stuck at a certain height after a while; the lastBlockHash returned by stats is the same as the corresponding slot from shelleyexplorer

Using trusted peers from Gerard 

[
  {
    "address": "/ip4/13.56.0.226/tcp/3000",
    "id": "7ddf203c86a012e8863ef19d96aabba23d2445c492d86267"
  },
  {
    "address": "/ip4/54.183.149.167/tcp/3000",
    "id": "df02383863ae5e14fea5d51a092585da34e689a73f704613"
  },
  {
    "address": "/ip4/52.9.77.197/tcp/3000",
    "id": "fcdf302895236d012635052725a0cdfc2e8ee394a1935b63"
  },
  {
    "address": "/ip4/18.177.78.96/tcp/3000",
    "id": "fc89bff08ec4e054b4f03106f5312834abdf2fcb444610e9"
  },
  {
    "address": "/ip4/3.115.154.161/tcp/3000",
    "id": "35bead7d45b3b8bda5e74aa12126d871069e7617b7f4fe62"
  },
  {
    "address": "/ip4/18.182.115.51/tcp/3000",
    "id": "8529e334a39a5b6033b698be2040b1089d8f67e0102e2575"
  },
  {
    "address": "/ip4/18.184.35.137/tcp/3000",
    "id": "06aa98b0ab6589f464d08911717115ef354161f0dc727858"
  },
  {
    "address": "/ip4/3.125.31.84/tcp/3000",
    "id": "8f9ff09765684199b351d520defac463b1282a63d3cc99ca"
  },
  {
    "address": "/ip4/3.125.183.71/tcp/3000",
    "id": "9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67"
  }
]

Using the tweaks from https://gist.github.com/ilap/54027fe9af0513c2701dc556221198b2

hexadecimal-pool picture hexadecimal-pool on 22 Dec 2019

are you seeing this issue with 0.8.5-alph1 or -alpha2 ?

jcli 0.8.5-alpha1 (HEAD-5d28516, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]
jormungandr 0.8.5-alpha1 (HEAD-5d28516, release, linux [x86_64]) - [rustc 1.40.0 (73528e339 2019-12-16)]

Dec 22 12:11:46.033 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:11:47.279 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:11:52.996 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:13:31.510 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 12:13:31.624 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 12:13:31.806 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:13:32.016 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:20:28.721 ERRO cannot process network blocks, reason: deadline has elapsed, task: block
Dec 22 12:27:42.034 WARN request timed out or failed unexpectedly, error: Error(Elapsed), request: GetHeadersRange, task: client-query
Dec 22 12:28:52.389 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:54.113 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:54.710 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:54.988 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:56.373 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:56.749 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:57.047 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:57.286 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:57.321 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:28:59.767 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:00.168 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:00.279 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:00.544 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:01.509 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:01.700 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:02.315 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:04.379 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:05.140 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:08.688 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:11.659 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:13.305 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:17.092 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:29:28.745 WARN response canceled by the processing task, request: UploadBlocks, sub_task: server, task: network
Dec 22 12:35:13.978 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:15.809 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:16.488 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:17.464 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:17.792 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:17.939 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:35:45.179 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:36:32.417 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 12:36:37.548 ERRO cannot process network blocks, reason: deadline has elapsed, task: block

redoracle picture redoracle on 22 Dec 2019

jormungandr 0.8.5-alpha3-aa5f63b

Dec 22 18:52:50.130 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 18:52:50.610 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.703 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.705 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.708 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.712 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.719 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.719 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:52:50.731 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 22 18:53:27.923 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 18:53:27.930 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 18:53:27.931 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 22 18:53:27.931 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network

also, node is stuck

lastBlockTime: "2019-12-22T17:47:35+00:00"
lastBlockTx: 1
lastReceivedBlockTime: "2019-12-22T17:56:56+00:00"
timo89 picture timo89 on 22 Dec 2019

DEC 23 - jormungandr 0.8.5
Dec 23 16:19:24.881 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.881 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network blocks, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network blocks, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.882 ERRO cannot process network headers, reason: deadline has elapsed, task: block
Dec 23 16:19:24.883 ERRO cannot process network headers, reason: deadline has elapsed, task: block

ghost picture ghost on 23 Dec 2019

Happening for me in prerelease of 8.5 as well

stanfieldr picture stanfieldr on 24 Dec 2019

Same for me in 0.8.5.

mmahut picture mmahut on 25 Dec 2019
👍6

Should be taking no longer than 60s to process the headers of incoming blocks to cause this error. Could be caused by incoming invalid blocks or when running on a fork; as far as I can tell the header processing is async; if blocks arrive out of order they are kept in queue, after 60s if no valid block with HASH = PREVIOUS_BLOCK_HASH is received to put them back in order they get discarded and this error may appear as I don't see these kind of blocks discarded elsewhere in the code.

mark-stopka picture mark-stopka on 25 Dec 2019

obrazek

same, restarting (w deleting storage) not helping now. 0.8.5.

cardanians picture cardanians on 27 Dec 2019

Same for me on 0.8.5 . Refer log details below. And block height get stuck after some time once i see this errors starts coming .

Dec 30 13:50:34.829 WARN unable to reach peer for initial bootstrap, reason: HTTP/2.0 connection error, peer_addr: 52.28.91.178:3000, task: bootstrap
Dec 30 13:51:50.170 WARN unable to reach peer for initial bootstrap, reason: HTTP/2.0 connection error, peer_addr: 3.124.116.145:3000, task: bootstrap
Dec 30 14:05:34.430 WARN request timed out or failed unexpectedly, error: Error(Elapsed), request: GetHeadersRange, task: client-query
Dec 30 14:09:35.614 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:21:13.275 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:22:25.476 ERRO cannot process network blocks, reason: deadline has elapsed, task: block
Dec 30 14:25:16.289 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:25:33.687 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:26:03.481 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:29:41.707 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:30:44.026 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:31:25.473 WARN response canceled by the processing task, request: UploadBlocks, sub_task: server, task: network
Dec 30 14:34:27.564 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:36:26.712 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network
Dec 30 14:36:27.344 WARN response canceled by the processing task, request: PushHeaders, sub_task: server, task: network

BitcoinMicroPaymentNetwork picture BitcoinMicroPaymentNetwork on 30 Dec 2019

When hitting this error, my CPU spikes to 100% utilization and I have following additional information in the logs


Dec 31 00:27:25.818 INFO peer adaadaadaada000000000000000000000000000000000088 not available to solicit blocks from, task: network
Dec 31 00:27:25.823 INFO peer b187100984cc9393a95af0a6c560a0fa14d00521dc576c1c not available to solicit blocks from, task: network
Dec 31 00:27:25.823 INFO peer 11d2214af7f452aa83187e2c63741fdeca93c015bdb68ca5 not available to solicit blocks from, task: network
Dec 31 00:27:25.823 INFO peer 4834deff494dd4ad213bb6583ea3fb4058cd4157f96e6f85 not available to solicit blocks from, task: network
Dec 31 00:27:25.823 INFO peer b187100984cc9393a95af0a6c560a0fa14d00521dc576c1c not available to pull headers from, task: network
Dec 31 00:27:34.191 INFO create new branch, task: block
Dec 31 00:27:50.831 INFO connecting to peer, node_id: 384161dec7dc1dd126e0da602f76a527d6a38590fd15be78, peer_addr: 18.144.37.15:3000, task: network
Dec 31 00:28:22.116 ERRO cannot process network blocks, reason: deadline has elapsed, task: block
Dec 31 00:28:34.192 INFO create new branch, task: block
Dec 31 00:29:34.197 INFO create new branch, task: block
Dec 31 00:30:34.192 INFO create new branch, task: block
Dec 31 00:31:34.201 INFO create new branch, task: block
Dec 31 00:32:34.192 INFO create new branch, task: block
mark-stopka picture mark-stopka on 31 Dec 2019

and ? which is the solution ? Today I 've restarted more than 10 times... All users has this error... (lastBlockTime locked)

keynobase picture keynobase on 31 Dec 2019
😕1

I've noticed these errors coincide with the CPU reaching 100% for the jormungandr process.
TOP's thread view shows the networking threads are consuming the most CPU.
Here is a screenshot of TOP during one of those events:
image

JamesRobertKelley picture JamesRobertKelley on 2 Jan 2020
👍1

Any update on what is happening with this issue? I'm seeing it in 0.8.5 as well.

dmindfuse picture dmindfuse on 14 Jan 2020

Same issue on 0.8.6

Jamanis picture Jamanis on 28 Jan 2020

Jan 30 20:06:07.087 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:07.093 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:07.094 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:07.095 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:07.098 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:09.239 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:09.247 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:09.963 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:09.965 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:09.980 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:17.087 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:17.090 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:17.093 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:17.095 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:17.099 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:19.240 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:19.249 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:19.966 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:19.979 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:19.987 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:27.086 INFO create new branch with tip cd483a83-00023e3b-47.42668 | current-tip 0a6edf26-00023e48-47.42948, task: block Jan 30 20:06:27.092 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:27.102 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:27.108 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:27.119 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:27.129 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:29.240 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:29.245 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:29.979 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:29.988 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:29.999 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:37.086 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:37.088 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:37.089 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:37.091 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:37.092 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:39.239 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:39.249 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:39.964 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:39.966 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:39.967 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:47.087 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:47.094 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:47.105 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:47.116 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:47.125 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:49.244 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network Jan 30 20:06:49.253 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:49.968 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:49.988 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:49.989 INFO failed to connect to peer, reason: Connection refused (os error 111), node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:57.087 INFO connecting to peer, node_id: 7ddf203c86a012e8863ef19d96aabba23d2445c492d86267, peer_addr: 13.56.0.226:3000, task: network Jan 30 20:06:57.089 INFO connecting to peer, node_id: df02383863ae5e14fea5d51a092585da34e689a73f704613, peer_addr: 54.183.149.167:3000, task: network Jan 30 20:06:57.091 INFO connecting to peer, node_id: 06aa98b0ab6589f464d08911717115ef354161f0dc727858, peer_addr: 18.184.35.137:3000, task: network Jan 30 20:06:57.093 INFO connecting to peer, node_id: fcdf302895236d012635052725a0cdfc2e8ee394a1935b63, peer_addr: 52.9.77.197:3000, task: network Jan 30 20:06:57.095 INFO connecting to peer, node_id: 9d15a9e2f1336c7acda8ced34e929f697dc24ea0910c3e67, peer_addr: 3.125.183.71:3000, task: network

Same on 0.8.7, 0.8.8

Kaze1337 picture Kaze1337 on 30 Jan 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

hemants1 picture hemants1  路  14Comments
MarcelKlammer picture MarcelKlammer  路  12Comments
dorin100 picture dorin100  路  13Comments
Linicks picture Linicks  路  13Comments
jbgi picture jbgi  路  29Comments