snarkOS icon indicating copy to clipboard operation
snarkOS copied to clipboard
verified publisher icon AleoNet

[Bug] The prover is not receiving tasks from the pool operator even if both are in "Ready" status

Open alextop opened this issue 3 years ago • 2 comments

🐛 Bug Report

The prover declares its status as "Ready", the pool operator declares its status as "Ready" but the prover is not receiving the tasks from the operator and does not try to process the proofs. The result is very low CPU consumption and wasting the server's uptime.

Steps to Reproduce

This depends on the network connections, hard to reproduce, probably operator logs can show something.

The prover log is the following:

Feb 03 21:37:11 root1822 snarkos[1088812]: 2022-02-03T20:37:11.026436Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254929, cumulative_weight = 89707596354, block_requests = 0, connected_peers = 14)
Feb 03 21:37:11 root1822 snarkos[1088812]: 2022-02-03T20:37:11.648580Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:11 root1822 snarkos[1088812]: 2022-02-03T20:37:11.648617Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:11 root1822 snarkos[1088812]: 2022-02-03T20:37:11.649702Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:12 root1822 snarkos[1088812]: 2022-02-03T20:37:12.650874Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:13 root1822 snarkos[1088812]: 2022-02-03T20:37:13.651077Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:14 root1822 snarkos[1088812]: 2022-02-03T20:37:14.651971Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:15 root1822 snarkos[1088812]: 2022-02-03T20:37:15.653040Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:16 root1822 snarkos[1088812]: 2022-02-03T20:37:16.654105Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:17 root1822 snarkos[1088812]: 2022-02-03T20:37:17.655814Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:18 root1822 snarkos[1088812]: 2022-02-03T20:37:18.656880Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:19 root1822 snarkos[1088812]: 2022-02-03T20:37:19.658212Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:20 root1822 snarkos[1088812]: 2022-02-03T20:37:20.659878Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:21 root1822 snarkos[1088812]: 2022-02-03T20:37:21.661051Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:22 root1822 snarkos[1088812]: 2022-02-03T20:37:22.662096Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:23 root1822 snarkos[1088812]: 2022-02-03T20:37:23.663162Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:24 root1822 snarkos[1088812]: 2022-02-03T20:37:24.664245Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:25 root1822 snarkos[1088812]: 2022-02-03T20:37:25.665288Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:26 root1822 snarkos[1088812]: 2022-02-03T20:37:26.254949Z DEBUG Skipping connection request to 35.228.82.203:4132 (already connected)
Feb 03 21:37:26 root1822 snarkos[1088812]: 2022-02-03T20:37:26.666421Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:27 root1822 snarkos[1088812]: 2022-02-03T20:37:27.666976Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:28 root1822 snarkos[1088812]: 2022-02-03T20:37:28.668041Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:29 root1822 snarkos[1088812]: 2022-02-03T20:37:29.669168Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:30 root1822 snarkos[1088812]: 2022-02-03T20:37:30.670699Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:31 root1822 snarkos[1088812]: 2022-02-03T20:37:31.671296Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:32 root1822 snarkos[1088812]: 2022-02-03T20:37:32.672380Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:33 root1822 snarkos[1088812]: 2022-02-03T20:37:33.605271Z DEBUG Peer 35.228.82.203:4132 is at block 254930 (type = Operator, status = Ready, is_fork = false, cumulative_weight = 89708073891, common_ancestor = 254929)
Feb 03 21:37:33 root1822 snarkos[1088812]: 2022-02-03T20:37:33.673478Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:34 root1822 snarkos[1088812]: 2022-02-03T20:37:34.674503Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:35 root1822 snarkos[1088812]: 2022-02-03T20:37:35.675584Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:36 root1822 snarkos[1088812]: 2022-02-03T20:37:36.676512Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:37 root1822 snarkos[1088812]: 2022-02-03T20:37:37.677494Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:38 root1822 snarkos[1088812]: 2022-02-03T20:37:38.678578Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:39 root1822 snarkos[1088812]: 2022-02-03T20:37:39.679932Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:40 root1822 snarkos[1088812]: 2022-02-03T20:37:40.681004Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:41 root1822 snarkos[1088812]: 2022-02-03T20:37:41.682109Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:42 root1822 snarkos[1088812]: 2022-02-03T20:37:42.683158Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:43 root1822 snarkos[1088812]: 2022-02-03T20:37:43.684238Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:52 root1822 snarkos[1088812]: 2022-02-03T20:37:52.910455Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254930, cumulative_weight = 89708074077, block_requests = 0, connected_peers = 13)
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098522Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254931, cumulative_weight = 89708551895, block_requests = 0, connected_peers = 13)
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098613Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098661Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098676Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098684Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098691Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.098697Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.165441Z TRACE Preparing to send 'UnconfirmedBlock 254931' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.165444Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.167718Z TRACE Preparing to send 'UnconfirmedBlock 254930' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.167720Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.172882Z TRACE Preparing to send 'UnconfirmedBlock 254931' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.172884Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.176950Z TRACE Preparing to send 'UnconfirmedBlock 254930' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.176953Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.187405Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254931, cumulative_weight = 89708551895, block_requests = 0, connected_peers = 13)
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.232013Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254931, cumulative_weight = 89708551895, block_requests = 0, connected_peers = 13)
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.456503Z TRACE Preparing to send 'UnconfirmedBlock 254932' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.456514Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.614381Z TRACE Preparing to send 'UnconfirmedBlock 254929' to 35.228.82.203:4132
Feb 03 21:37:53 root1822 snarkos[1088812]: 2022-02-03T20:37:53.614385Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:37:56 root1822 snarkos[1088812]: 2022-02-03T20:37:56.031238Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254932, cumulative_weight = 89709029811, block_requests = 0, connected_peers = 13)
Feb 03 21:37:56 root1822 snarkos[1088812]: 2022-02-03T20:37:56.256739Z DEBUG Skipping connection request to 35.228.82.203:4132 (already connected)
Feb 03 21:37:56 root1822 snarkos[1088812]: 2022-02-03T20:37:56.699423Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:57 root1822 snarkos[1088812]: 2022-02-03T20:37:57.700884Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:58 root1822 snarkos[1088812]: 2022-02-03T20:37:58.701961Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:37:59 root1822 snarkos[1088812]: 2022-02-03T20:37:59.703062Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:00 root1822 snarkos[1088812]: 2022-02-03T20:38:00.704200Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:01 root1822 snarkos[1088812]: 2022-02-03T20:38:01.705413Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:02 root1822 snarkos[1088812]: 2022-02-03T20:38:02.706742Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:03 root1822 snarkos[1088812]: 2022-02-03T20:38:03.321085Z TRACE Preparing to send 'UnconfirmedBlock 254932' to 35.228.82.203:4132
Feb 03 21:38:03 root1822 snarkos[1088812]: 2022-02-03T20:38:03.321087Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:38:03 root1822 snarkos[1088812]: 2022-02-03T20:38:03.707504Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:04 root1822 snarkos[1088812]: 2022-02-03T20:38:04.708530Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:05 root1822 snarkos[1088812]: 2022-02-03T20:38:05.032051Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254932, cumulative_weight = 89709029811, block_requests = 0, connected_peers = 13)
Feb 03 21:38:05 root1822 snarkos[1088812]: 2022-02-03T20:38:05.700558Z TRACE Preparing to send 'UnconfirmedBlock 254933' to 35.228.82.203:4132
Feb 03 21:38:05 root1822 snarkos[1088812]: 2022-02-03T20:38:05.700560Z TRACE Sending 'UnconfirmedBlock' to 35.228.82.203:4132
Feb 03 21:38:11 root1822 snarkos[1088812]: 2022-02-03T20:38:11.649686Z TRACE Sending 'Ping' to 35.228.82.203:4132
Feb 03 21:38:11 root1822 snarkos[1088812]: 2022-02-03T20:38:11.828454Z TRACE Received 'Pong' from 35.228.82.203:4132
Feb 03 21:38:14 root1822 snarkos[1088812]: 2022-02-03T20:38:14.036583Z DEBUG Status Report (type = Prover, status = Ready, block_height = 254933, cumulative_weight = 89709507826, block_requests = 0, connected_peers = 13)
Feb 03 21:38:14 root1822 snarkos[1088812]: 2022-02-03T20:38:14.722462Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:15 root1822 snarkos[1088812]: 2022-02-03T20:38:15.723184Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:16 root1822 snarkos[1088812]: 2022-02-03T20:38:16.726225Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:17 root1822 snarkos[1088812]: 2022-02-03T20:38:17.727547Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:18 root1822 snarkos[1088812]: 2022-02-03T20:38:18.728442Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:19 root1822 snarkos[1088812]: 2022-02-03T20:38:19.516807Z DEBUG Peer 35.228.82.203:4132 is at block 254932 (type = Operator, status = Ready, is_fork = undecided, cumulative_weight = 89709028930, common_ancestor = 254929)
Feb 03 21:38:19 root1822 snarkos[1088812]: 2022-02-03T20:38:19.728943Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:20 root1822 snarkos[1088812]: 2022-02-03T20:38:20.730077Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:21 root1822 snarkos[1088812]: 2022-02-03T20:38:21.731129Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:22 root1822 snarkos[1088812]: 2022-02-03T20:38:22.995399Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:23 root1822 snarkos[1088812]: 2022-02-03T20:38:23.996500Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:24 root1822 snarkos[1088812]: 2022-02-03T20:38:24.997513Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:25 root1822 snarkos[1088812]: 2022-02-03T20:38:25.998083Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:26 root1822 snarkos[1088812]: 2022-02-03T20:38:26.257370Z DEBUG Skipping connection request to 35.228.82.203:4132 (already connected)
Feb 03 21:38:26 root1822 snarkos[1088812]: 2022-02-03T20:38:26.999890Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:28 root1822 snarkos[1088812]: 2022-02-03T20:38:28.001161Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:29 root1822 snarkos[1088812]: 2022-02-03T20:38:29.002303Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:30 root1822 snarkos[1088812]: 2022-02-03T20:38:30.242018Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:31 root1822 snarkos[1088812]: 2022-02-03T20:38:31.243739Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:32 root1822 snarkos[1088812]: 2022-02-03T20:38:32.244800Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:33 root1822 snarkos[1088812]: 2022-02-03T20:38:33.245641Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:34 root1822 snarkos[1088812]: 2022-02-03T20:38:34.246500Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:35 root1822 snarkos[1088812]: 2022-02-03T20:38:35.247533Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:36 root1822 snarkos[1088812]: 2022-02-03T20:38:36.248504Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:37 root1822 snarkos[1088812]: 2022-02-03T20:38:37.249784Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:38 root1822 snarkos[1088812]: 2022-02-03T20:38:38.249970Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:39 root1822 snarkos[1088812]: 2022-02-03T20:38:39.251024Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:40 root1822 snarkos[1088812]: 2022-02-03T20:38:40.252104Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:41 root1822 snarkos[1088812]: 2022-02-03T20:38:41.253195Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:42 root1822 snarkos[1088812]: 2022-02-03T20:38:42.254255Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:43 root1822 snarkos[1088812]: 2022-02-03T20:38:43.255796Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132
Feb 03 21:38:44 root1822 snarkos[1088812]: 2022-02-03T20:38:44.256501Z TRACE Sending 'PoolRegister' to 35.228.82.203:4132

This is repeating during almost all the time after connecting to the pool.

Expected Behavior

The operator should send the tasks to the prover, the prover should be constantly loaded with the proofs processing, CPU consumption is close to 100%.

Your Environment

  • snarkos 2.0.0
  • rustc 1.58.1 (db9d1b20b 2022-01-20)
  • Ubuntu 20.04
  • AMD Ryzen 3900x, 64GB RAM, 2*1TB NVMe Raid 0
  • 1GBPs network

alextop avatar Feb 03 '22 20:02 alextop

Further observations show, that after some point the prover stops producing proofs and sending PoolResponse messages (probably, because it switches to sync mode), after that, it starts to send PoolRegister messages but the operator does not respond to them.

alextop avatar Feb 03 '22 21:02 alextop

This will be investigated more closely, but CPU utilization will never be 100% at all times, as some of the cryptographic code is single-threaded by design.

ljedrz avatar Feb 04 '22 10:02 ljedrz

Closing, since this feature is now deprecated.

howardwu avatar Jun 16 '23 03:06 howardwu