search

Neptune-Crypto / neptune-core

anonymous peer-to-peer cash
Apache License 2.0
24 stars 7 forks source link

Deadlock in client #38

Closed Sword-Smith closed 6 months ago

Sword-Smith commented 1 year ago

Client froze. This was the info log I had. I'll run the client with debug logging to get a better clue about what's going on.

Reproduce error:

The client will now hang, probably because of a deadlock.

Tasks

The DeadlineExceeded error is from the neptune-dashboard RPC requests

023-08-12T10:34:22.448697393Z  INFO ThreadId(05) neptune_core::connect_to_peers: Connection closing
2023-08-12T10:34:29.474720181Z  WARN ThreadId(01) neptune_core::models::state: Could not recover MSMP as transaction appears to be on an abandoned chain
2023-08-12T10:34:29.683557059Z  WARN ThreadId(03) neptune_core::connect_to_peers: Failed to establish connection: Connection timed out (os error 110)
2023-08-12T10:34:29.68362634Z  INFO ThreadId(03) neptune_core::connect_to_peers: Connection closing
2023-08-12T10:34:41.543624886Z  INFO ThreadId(05) neptune_core::connect_to_peers: Established incoming TCP connection with 51.75.69.178:33932
2023-08-12T10:34:41.543854407Z  WARN ThreadId(04) neptune_core::connect_to_peers: Attempting to connect to incompatible version. You might have to upgrade, or the other node does. Own version: 0.0.3, other version: 0.0.0
2023-08-12T10:34:41.543879847Z  WARN ThreadId(04) neptune_core::connect_to_peers: Incoming connection refused: IncompatibleVersion
2023-08-12T10:34:41.543924937Z ERROR ThreadId(04) neptune_core::main_loop: Got error: Refusing incoming connection. Reason: IncompatibleVersion
2023-08-12T10:35:28.482573625Z  WARN ThreadId(01) neptune_core::models::state: Could not recover MSMP as transaction appears to be on an abandoned chain
2023-08-12T10:36:22.43128133Z  INFO ThreadId(01) neptune_core::main_loop: Attempting to reconnect to peer with lost connection: 31.164.230.171:9798
2023-08-12T10:36:22.431532531Z  INFO ThreadId(01) neptune_core::main_loop: Attempting to reconnect to peer with lost connection: 139.162.193.206:9798
2023-08-12T10:36:22.431579631Z  INFO ThreadId(01) neptune_core::main_loop: Performing peer discovery
2023-08-12T10:36:22.431598261Z  INFO ThreadId(01) neptune_core::main_loop: Connecting to peer 82.136.69.139:9798 with distance 2
2023-08-12T10:36:22.44041506Z  INFO ThreadId(03) neptune_core::connect_to_peers: Established outgoing TCP connection with 139.162.193.206:9798
2023-08-12T10:36:22.4494535Z ERROR ThreadId(04) neptune_core::connect_to_peers: An error occurred: Outgoing connection attempt refused. Reason: AlreadyConnected. Connection closing
2023-08-12T10:36:22.44950387Z  INFO ThreadId(04) neptune_core::connect_to_peers: Connection closing
2023-08-12T10:36:22.453033508Z  WARN ThreadId(04) neptune_core::connect_to_peers: Failed to establish connection: Connection refused (os error 111)
2023-08-12T10:36:22.453069528Z  INFO ThreadId(04) neptune_core::connect_to_peers: Connection closing
2023-08-12T10:36:22.538857681Z  INFO ThreadId(04) neptune_core::peer_loop: Got new block from peer 178.238.174.94:37920, block height 00000000000000000580
2023-08-12T10:36:22.539621193Z  INFO ThreadId(04) neptune_core::models::blockchain::transaction::validity: validity logic for 'kernel_to_lock_scripts', 'kernel_to_type_scripts', 'type_scripts_halt' not implemented yet.
2023-08-12T10:36:22.552173661Z  INFO ThreadId(04) neptune_core::peer_loop: Block with height 00000000000000000580 is valid
2023-08-12T10:36:22.552288731Z  INFO ThreadId(04) neptune_core::peer_loop: Updated block info by block from peer. block height 00000000000000000580
2023-08-12T10:36:22.569871131Z  WARN ThreadId(01) neptune_core::models::state::wallet::wallet_state: Unable to find valid membership proof for UTXO with digest 01398093405947558790,16816894808247695991,16743266564579333718,05859459522143639618,07769921081138901752
2023-08-12T10:36:22.63191612Z  INFO ThreadId(04) neptune_core::mine_loop: Mining thread got message from main
2023-08-12T10:36:22.63201702Z  INFO ThreadId(04) neptune_core::mine_loop: Miner thread received regtest block height 00000000000000000580
2023-08-12T10:36:22.6456262Z  INFO ThreadId(04) neptune_core::mine_loop: Mining on block with 2 outputs. Attempting to find block with height 00000000000000000581
2023-08-12T10:36:29.683555112Z  WARN ThreadId(02) neptune_core::connect_to_peers: Failed to establish connection: Connection timed out (os error 110)
2023-08-12T10:36:29.683621682Z  INFO ThreadId(02) neptune_core::connect_to_peers: Connection closing
2023-08-12T10:36:32.56082707Z ERROR ThreadId(02) tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-12T10:36:42.561841133Z ERROR ThreadId(05) tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-12T10:38:29.683549272Z  WARN ThreadId(05) neptune_core::connect_to_peers: Failed to establish connection: Connection timed out (os error 110)
2023-08-12T10:38:29.683613912Z  INFO ThreadId(05) neptune_core::connect_to_peers: Connection closing
2023-08-12T11:02:40.753888963Z  INFO ThreadId(05) neptune_core::mine_loop: Found valid block with nonce: (14644138258032336348, 02155941153240723463, 16138749623266008973).
2023-08-12T11:02:40.753948603Z  INFO ThreadId(05) neptune_core::mine_loop: PoW digest of new block: 06443209361902945120,03370880170143815716,03346985456245238821,06681898316157404331,00000013270377396205. Threshold was: 06443296562847379385,09275857750658948802,16317201652566676012,16422411294981116330,00000019850875927252
2023-08-12T11:02:40.754429614Z  INFO ThreadId(05) neptune_core::mine_loop: Found new regtest block with block height 00000000000000000581. Hash: [🤖🤣🍑|👏😉😋|🤑👏🥰|🙄😆😱|🤣🐶😰]

2023-08-12T14:37:26.495896044Z ERROR ThreadId(05) tarpc::server::in_flight_requests: DeadlineExceeded
Sword-Smith commented 1 year ago

Potentially another deadlock? All RPC calls failed, unable to shutdown client although the neptune-cli shutdown command reported success.

Client was failing on all RPC calls. Maybe deadline is too short? Or maybe an RPC call caused the deadlock? That's my current guess.

2023-08-16T08:11:26.057464965Z DEBUG ThreadId(17) neptune_core::peer_loop: Fetching parent block
2023-08-16T08:11:26.057514746Z DEBUG ThreadId(17) neptune_core::peer_loop: Completed parent block fetching from DB: found
2023-08-16T08:11:26.057535431Z DEBUG ThreadId(17) neptune_core::peer_loop: attempting to validate 2 blocks
2023-08-16T08:11:26.057621651Z  INFO ThreadId(17) neptune_core::models::blockchain::transaction::validity: validity logic for 'kernel_to_lock_scripts', 'kernel_to_type_scripts', 'type_scripts_halt' not implemented yet.
2023-08-16T08:11:26.060389732Z  INFO ThreadId(17) neptune_core::peer_loop: Block with height 00000000000000001112 is valid
2023-08-16T08:11:26.060460588Z  INFO ThreadId(17) neptune_core::models::blockchain::transaction::validity: validity logic for 'kernel_to_lock_scripts', 'kernel_to_type_scripts', 'type_scripts_halt' not implemented yet.
2023-08-16T08:11:26.063145235Z  INFO ThreadId(17) neptune_core::peer_loop: Block with height 00000000000000001113 is valid
2023-08-16T08:11:26.063152033Z  INFO ThreadId(17) neptune_core::peer_loop: Updated block info by block from peer. block height 00000000000000001113
2023-08-16T08:11:33.089762908Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:11:33.089781388Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:13:32.87892176Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:13:32.878940519Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:15:32.894454116Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:15:32.894473952Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:17:32.90960094Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:17:32.909620279Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:19:32.520792343Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:19:32.52081393Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:21:32.579405523Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:21:32.579424481Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:23:32.614924003Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:23:32.614947559Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:25:32.625833201Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:25:32.625857096Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:27:32.523797535Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:27:32.523817161Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:29:32.642788169Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:29:32.642808406Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:31:32.56452368Z DEBUG ThreadId(17) neptune_core::peer_loop: Received peer list req from peer 51.15.139.238:9798
2023-08-16T08:31:32.564543855Z DEBUG ThreadId(17) neptune_core::peer_loop: Responding with: [(51.15.139.238:9798, 214478992320878330789449361015234657487)]
2023-08-16T08:31:54.554031775Z  INFO ThreadId(17) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:04.553957617Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-16T08:31:54.554084314Z  INFO ThreadId(17) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:04.553957617Z otel.kind="server" otel.name="RPC.prune_abandoned_monitored_utxos"}: tarpc::server: BeginRequest
2023-08-16T08:32:04.555480202Z ERROR ThreadId(08) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:04.553957617Z otel.kind="server" otel.name="RPC.prune_abandoned_monitored_utxos"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-16T08:32:04.555596033Z DEBUG ThreadId(08) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0.0.1
2023-08-16T08:32:21.04164665Z  INFO ThreadId(08) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:31.041574615Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-16T08:32:21.041700913Z  INFO ThreadId(08) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:31.041574615Z otel.kind="server" otel.name="RPC.get_synced_balance"}: tarpc::server: BeginRequest
2023-08-16T08:32:31.043513697Z ERROR ThreadId(09) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:31.041574615Z otel.kind="server" otel.name="RPC.get_synced_balance"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-16T08:32:31.043616044Z DEBUG ThreadId(09) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0.0.1
2023-08-16T08:32:32.237913167Z  INFO ThreadId(09) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:42.237828392Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-16T08:32:32.23797795Z  INFO ThreadId(09) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:42.237828392Z otel.kind="server" otel.name="RPC.get_synced_balance"}: tarpc::server: BeginRequest
^C2023-08-16T08:32:34.254057083Z  INFO ThreadId(10) neptune_core::main_loop: Received SIGINT
2023-08-16T08:32:42.240430183Z ERROR ThreadId(10) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:32:42.237828392Z otel.kind="server" otel.name="RPC.get_synced_balance"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-16T08:32:42.240479602Z DEBUG ThreadId(10) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0.0.1
Sword-Smith commented 1 year ago

Calling neptune-cli prune-abandoned-monitored-utxos seems to crash the node. I cannot shut it down afterwards.

Notice that the client never shuts down in the below log although it does go through some of the shutdown procedures.

023-08-16T08:38:23.994941287Z  INFO ThreadId(14) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:33.994541988Z otel.kind="ser[0/1838]l.name="RPC.prune_abandoned_monitored_utxos"}: tarpc::server: BeginRequest
2023-08-16T08:38:33.692314156Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: block-synchronization job
2023-08-16T08:38:33.996609933Z ERROR ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:33.994541988Z otel.kind="server" ote
l.name="RPC.prune_abandoned_monitored_utxos"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-16T08:38:33.996899576Z DEBUG ThreadId(02) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0
.0.1
2023-08-16T08:38:40.672377445Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:50.672227910Z otel.kind="server"}: t
arpc::server: ReceiveRequest
2023-08-16T08:38:40.672440134Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:50.672227910Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BeginRequest
2023-08-16T08:38:40.672452314Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:50.672227910Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: CompleteRequest
2023-08-16T08:38:40.672457726Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:50.672227910Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BufferResponse
2023-08-16T08:38:40.67246328Z  INFO ThreadId(01) neptune_core::main_loop: Recived RPC shutdown request.
2023-08-16T08:38:40.672468747Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:38:50.672227910Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: SendResponse
2023-08-16T08:38:40.672472908Z  INFO ThreadId(01) neptune_core::main_loop: Shutdown initiated.
2023-08-16T08:38:40.67247923Z DEBUG ThreadId(01) neptune_core::main_loop: sent bye
2023-08-16T08:38:40.672498735Z  INFO ThreadId(16) neptune_core::mine_loop: Mining thread got message from main
2023-08-16T08:38:40.672498523Z DEBUG ThreadId(13) neptune_core::peer_loop: Handling disconnect all message from main in peer loop
2023-08-16T08:38:40.672506955Z DEBUG ThreadId(16) neptune_core::mine_loop: Miner shutting down.
2023-08-16T08:38:40.672511239Z DEBUG ThreadId(16) neptune_core::mine_loop: Miner shut down gracefully.
2023-08-16T08:38:40.672510376Z  INFO ThreadId(13) neptune_core::peer_loop: handle_main_thread_message is closing the connection to 51.15
.139.238:9798
2023-08-16T08:38:40.672552702Z DEBUG ThreadId(13) neptune_core::peer_loop: Exited peer loop for 51.15.139.238:9798
2023-08-16T08:38:40.672559253Z DEBUG ThreadId(13) neptune_core::connect_to_peers: Fetched peer info standing for 51.15.139.238:9798
2023-08-16T08:38:40.67256925Z DEBUG ThreadId(13) neptune_core::connect_to_peers: Stored peer info standing for 51.15.139.238:9798
2023-08-16T08:38:40.672575156Z DEBUG ThreadId(13) neptune_core::peer_loop: Ending peer loop for 51.15.139.238:9798
2023-08-16T08:38:40.672582032Z  INFO ThreadId(13) neptune_core::connect_to_peers: Connection closing
2023-08-16T08:38:40.672636693Z DEBUG ThreadId(02) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0
.0.1
2023-08-16T08:39:07.259452318Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.259380880Z otel.kind="server"}: t
arpc::server: ReceiveRequest
2023-08-16T08:39:07.259523278Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.259380880Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BeginRequest
2023-08-16T08:39:07.259533388Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.259380880Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: CompleteRequest
2023-08-16T08:39:07.259538725Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.259380880Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BufferResponse
2023-08-16T08:39:07.259571841Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.259380880Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: SendResponse
2023-08-16T08:39:07.259799084Z DEBUG ThreadId(15) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0
.0.1
2023-08-16T08:39:07.753069558Z  INFO ThreadId(15) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.752995876Z otel.kind="server"}: t
arpc::server: ReceiveRequest
2023-08-16T08:39:07.753119147Z  INFO ThreadId(15) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.752995876Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BeginRequest
2023-08-16T08:39:07.753126582Z  INFO ThreadId(15) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.752995876Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: CompleteRequest
2023-08-16T08:39:07.753131352Z  INFO ThreadId(15) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.752995876Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BufferResponse
2023-08-16T08:39:07.753138488Z  INFO ThreadId(15) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:17.752995876Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: SendResponse
2023-08-16T08:39:07.753319018Z DEBUG ThreadId(02) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0
.0.1
2023-08-16T08:39:08.149533116Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:18.149466345Z otel.kind="server"}: t
arpc::server: ReceiveRequest
2023-08-16T08:39:08.149565956Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:18.149466345Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BeginRequest
2023-08-16T08:39:08.149574998Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:18.149466345Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: CompleteRequest
2023-08-16T08:39:08.149579973Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:18.149466345Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: BufferResponse
2023-08-16T08:39:08.149590252Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-16T08:39:18.149466345Z otel.kind="server" ote
l.name="RPC.shutdown"}: tarpc::server: SendResponse
2023-08-16T08:39:08.149688097Z DEBUG ThreadId(15) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0
.0.1
^C2023-08-16T08:39:09.545900034Z  INFO ThreadId(15) neptune_core::main_loop: Received SIGINT
Sword-Smith commented 1 year ago

Another deadlock, I think. This time with DEBUG logging. Seems to be right after a block was found.

2023-08-19T07:47:14.354169228Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Block has 0 removal records
2023-08-19T07:47:14.354216488Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Transaction has 0 inputs
2023-08-19T07:47:14.354273088Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Number of mutated membership proofs: 0
2023-08-19T07:47:14.374651024Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Number of unspent UTXOs: 867
2023-08-19T07:47:14.490288752Z DEBUG ThreadId(04) neptune_core::peer_loop: Received block notification from peer 139.162.193.206:56484
2023-08-19T07:47:14.490320262Z DEBUG ThreadId(04) neptune_core::peer_loop: Got BlockNotification of height 00000000000000001657
2023-08-19T07:47:14.728923438Z DEBUG ThreadId(01) neptune_core::main_loop: Flushed all databases
2023-08-19T07:47:14.729023168Z  INFO ThreadId(03) neptune_core::mine_loop: Mining thread got message from main
2023-08-19T07:47:14.729064108Z  INFO ThreadId(03) neptune_core::mine_loop: Miner thread received regtest block height 00000000000000001657
2023-08-19T07:47:14.729068018Z DEBUG ThreadId(04) neptune_core::peer_loop: Handling block message from main in peer loop
2023-08-19T07:47:14.735124705Z DEBUG ThreadId(03) neptune_core::models::blockchain::transaction::validity: Removal Records Integrity program digest: (03232888943305667770,04050339554097196106,12740911886741076582,10418451140009484127,09822177690473340989)
2023-08-19T07:47:14.739986798Z DEBUG ThreadId(03) neptune_core::mine_loop: Creating block transaction with mutator set hash: [😱😅😆|🐷😰👏|🤑💩😱|🐍👏😍|🐶😂🐍]
2023-08-19T07:47:14.740259739Z  INFO ThreadId(03) neptune_core::mine_loop: Mining on block with 1 outputs. Attempting to find block with height 00000000000000001658
2023-08-19T07:47:15.501498503Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: block-synchronization job
2023-08-19T07:47:24.472557349Z ERROR ThreadId(02) tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-19T07:47:25.503085682Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: block-synchronization job
2023-08-19T07:47:28.515440599Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: Membership proof resync job
2023-08-19T07:47:34.474274038Z ERROR ThreadId(04) tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-19T07:49:08.21663128Z DEBUG ThreadId(04) neptune_core::peer_loop: Received peer list req from peer 178.238.174.94:43928
2023-08-19T07:49:08.21670938Z DEBUG ThreadId(04) neptune_core::peer_loop: Responding with: [(139.162.193.206:9798, 64232866295818542391093629608719648170), (178.238.174.94:9798, 259782438598595915725339615281090129508)]
2023-08-19T07:50:44.06072232Z DEBUG ThreadId(04) neptune_core::peer_loop: Received block notification from peer 178.238.174.94:43928
2023-08-19T07:50:44.06075784Z DEBUG ThreadId(04) neptune_core::peer_loop: Got BlockNotification of height 00000000000000001658
2023-08-19T07:59:13.404652192Z  INFO ThreadId(02) neptune_core::mine_loop: Found valid block with nonce: (00881827036687447584, 13809404995063930820, 16039622816135605220).
2023-08-19T07:59:13.404732003Z  INFO ThreadId(02) neptune_core::mine_loop: PoW digest of new block: 17624691625543385462,07332291107629320781,18427168774048214834,06541959960128906460,00000010608583508352. Threshold was: 05931400167838197468,02068349005397865320,13238049361041661509,08951412108256889446,00000014057682541631
2023-08-19T07:59:13.404767013Z DEBUG ThreadId(02) neptune_core::mine_loop: Worker thread reports new block of height 00000000000000001658
2023-08-19T07:59:13.404869443Z  INFO ThreadId(02) neptune_core::models::blockchain::transaction::validity: validity logic for 'kernel_to_lock_scripts', 'kernel_to_type_scripts', 'type_scripts_halt' not implemented yet.
2023-08-19T07:59:13.410103387Z  INFO ThreadId(02) neptune_core::mine_loop: Found new regtest block with block height 00000000000000001658. Hash: [😉😰🤐|🤑💩👍|🍆💩👽|😉😋😆|🐱🤖👎]
Sword-Smith commented 1 year ago

In what seems to be another deadlock

2023-08-22T11:44:16.921652975Z DEBUG ThreadId(01) neptune_core::main_loop: Flushed all databases
2023-08-22T11:44:16.921888885Z DEBUG ThreadId(04) neptune_core::peer_loop: Handling block message from main in peer loop
2023-08-22T11:44:16.922004086Z  INFO ThreadId(05) neptune_core::mine_loop: Mining thread got message from main
2023-08-22T11:44:16.922088476Z  INFO ThreadId(05) neptune_core::mine_loop: Miner thread received regtest block height 00000000000000002117
2023-08-22T11:44:16.931539343Z DEBUG ThreadId(05) neptune_core::models::blockchain::transaction::validity: Removal Records Integrity program digest: (03232888943305667770,04050339554097196106,12740911886741076582,10418451140009484127,09822177690473340989)
2023-08-22T11:44:16.939616366Z DEBUG ThreadId(05) neptune_core::mine_loop: Creating block transaction with mutator set hash: [🐭🤣🥰|😉🐍🐱|😴🎂🤐|🐭🐷😅|😉😘🍆]
2023-08-22T11:44:16.940174518Z  INFO ThreadId(05) neptune_core::mine_loop: Mining on block with 1 outputs. Attempting to find block with height 00000000000000002118
2023-08-22T11:44:22.929482183Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: block-synchronization job
2023-08-22T11:44:24.473142095Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: peer discovery job
2023-08-22T11:44:24.473276825Z  INFO ThreadId(01) neptune_core::main_loop: Attempting to reconnect to peer with lost connection: 31.164.230.171:9798
2023-08-22T11:44:26.269618082Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-22T11:44:36.269524542Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-22T11:44:26.269787562Z  INFO ThreadId(02) RPC{rpc.trace_id=00 rpc.deadline=2023-08-22T11:44:36.269524542Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server: BeginRequest
2023-08-22T11:44:26.270266654Z ERROR ThreadId(05) RPC{rpc.trace_id=00 rpc.deadline=2023-08-22T11:44:26.268702508Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-22T11:44:36.270019472Z ERROR ThreadId(05) RPC{rpc.trace_id=00 rpc.deadline=2023-08-22T11:44:36.269524542Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-22T11:44:36.270236163Z DEBUG ThreadId(05) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0.0.12023-08-22T11:46:15.175831276Z DEBUG ThreadId(05) neptune_core::peer_loop: Received peer list req from peer 178.238.174.94:32659
2023-08-22T11:46:15.175893986Z DEBUG ThreadId(05) neptune_core::peer_loop: Responding with: [(139.162.193.206:9798, 64232866295818542391093629608719648170), (146.4.66.241:9798, 98622709369540652852683435731670875531), (178.238.174.94:9798, 280183946283835268166122758144850388721)]
2023-08-22T11:48:15.177241183Z DEBUG ThreadId(05) neptune_core::peer_loop: Received peer list req from peer 178.238.174.94:32659
2023-08-22T11:48:15.177312843Z DEBUG ThreadId(05) neptune_core::peer_loop: Responding with: [(139.162.193.206:9798, 64232866295818542391093629608719648170), (146.4.66.241:9798, 98622709369540652852683435731670875531), (178.238.174.94:9798, 280183946283835268166122758144850388721)]
2023-08-22T11:50:15.178035212Z DEBUG ThreadId(04) neptune_core::peer_loop: Received peer list req from peer 178.238.174.94:32659
2023-08-22T11:50:15.178110882Z DEBUG ThreadId(04) neptune_core::peer_loop: Responding with: [(139.162.193.206:9798, 64232866295818542391093629608719648170), (146.4.66.241:9798, 98622709369540652852683435731670875531), (178.238.174.94:9798, 280183946283835268166122758144850388721)]
2023-08-22T11:50:45.294758561Z DEBUG ThreadId(04) neptune_core::peer_loop: Received block notification from peer 178.238.174.94:32659
2023-08-22T11:50:45.294841431Z DEBUG ThreadId(04) neptune_core::peer_loop: Got BlockNotification of height 00000000000000002118
2023-08-22T11:55:12.287044858Z  INFO ThreadId(04) neptune_core::mine_loop: Found valid block with nonce: (08390761232875957234, 10754251800112537085, 13430963931536895894).
2023-08-22T11:55:12.287235518Z  INFO ThreadId(04) neptune_core::mine_loop: PoW digest of new block: 16024950464886911739,07339618466788491125,06381984541239381966,12647019092547475693,00000008457270903389. Threshold was: 13909879305770447135,17008779537175090666,01848807411131295381,07002023229822260803,00000014456118187607
2023-08-22T11:55:12.287312889Z DEBUG ThreadId(04) neptune_core::mine_loop: Worker thread reports new block of height 00000000000000002118
2023-08-22T11:55:12.287430279Z  INFO ThreadId(04) neptune_core::models::blockchain::transaction::validity: validity logic for 'kernel_to_lock_scripts', 'kernel_to_type_scripts', 'type_scripts_halt' not implemented yet.
2023-08-22T11:55:12.298686051Z  INFO ThreadId(04) neptune_core::mine_loop: Found new regtest block with block height 00000000000000002118. Hash: [😂🐷👍|😂😴😴|🍆🎂🐱|👏😎🤖|😴🍆😂]
2023-08-23T21:34:10.85541206Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.854350788Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-23T21:34:10.855933912Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.854350788Z otel.kind="server" otel.name="RPC.get_network"}: tarpc::server: BeginRequest
2023-08-23T21:34:10.855998982Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.854350788Z otel.kind="server" otel.name="RPC.get_network"}: tarpc::server: CompleteRequest
2023-08-23T21:34:10.856032292Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.854350788Z otel.kind="server" otel.name="RPC.get_network"}: tarpc::server: BufferResponse
2023-08-23T21:34:10.856108252Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.854350788Z otel.kind="server" otel.name="RPC.get_network"}: tarpc::server: SendResponse
2023-08-23T21:34:10.856593294Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.856463983Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-23T21:34:10.856682334Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.856463983Z otel.kind="server" otel.name="RPC.get_listen_address_for_peers"}: tarpc::server: BeginRequest
2023-08-23T21:34:10.856709604Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.856463983Z otel.kind="server" otel.name="RPC.get_listen_address_for_peers"}: tarpc::server: CompleteRequest
2023-08-23T21:34:10.856726504Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.856463983Z otel.kind="server" otel.name="RPC.get_listen_address_for_peers"}: tarpc::server: BufferResponse
2023-08-23T21:34:10.856765674Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.856463983Z otel.kind="server" otel.name="RPC.get_listen_address_for_peers"}: tarpc::server: SendResponse
2023-08-23T21:34:10.86242382Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.862241489Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-23T21:34:10.86250691Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-23T21:34:20.862241489Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server: BeginRequest
Sword-Smith commented 1 year ago

Deadlock. Maybe because of the TIMER log message?

2023-08-24T13:46:49.069275299Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Block has 0 removal records
2023-08-24T13:46:49.069337399Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Transaction has 0 inputs
2023-08-24T13:46:49.069381119Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Number of mutated membership proofs: 3
2023-08-24T13:46:49.103160096Z DEBUG ThreadId(01) neptune_core::models::state::wallet::wallet_state: Number of unspent UTXOs: 1075
2023-08-24T13:46:49.28814896Z DEBUG ThreadId(04) neptune_core::peer_loop: Received block notification from peer 139.162.193.206:9798
2023-08-24T13:46:49.28820816Z DEBUG ThreadId(04) neptune_core::peer_loop: Got BlockNotification of height 00000000000000002459
2023-08-24T13:46:49.508390436Z DEBUG ThreadId(04) neptune_core::peer_loop: Received block notification from peer 146.4.66.241:36826
2023-08-24T13:46:49.508537496Z DEBUG ThreadId(04) neptune_core::peer_loop: Got BlockNotification of height 00000000000000002459
2023-08-24T13:46:49.839618043Z DEBUG ThreadId(01) neptune_core::main_loop: Flushed all databases
2023-08-24T13:46:49.839795594Z  INFO ThreadId(04) neptune_core::mine_loop: Mining thread got message from main
2023-08-24T13:46:49.839823264Z  INFO ThreadId(04) neptune_core::mine_loop: Miner thread received regtest block height 00000000000000002459
2023-08-24T13:46:49.839901864Z DEBUG ThreadId(02) neptune_core::peer_loop: Handling block message from main in peer loop
2023-08-24T13:46:49.845382438Z DEBUG ThreadId(04) neptune_core::models::blockchain::transaction::validity: Removal Records Integrity program digest: (03232888943305667770,04050339554097196106,12740911886741076582,10418451140009484127,09822177690473340989)
2023-08-24T13:46:49.85012036Z DEBUG ThreadId(04) neptune_core::mine_loop: Creating block transaction with mutator set hash: [🤣🥰😘|🤑😰😱|🐭👽🍆|😅😎👎|💦🤐😍]
2023-08-24T13:46:49.85032652Z  INFO ThreadId(04) neptune_core::mine_loop: Mining on block with 1 outputs. Attempting to find block with height 00000000000000002460
2023-08-24T13:46:55.147209397Z DEBUG ThreadId(01) neptune_core::main_loop: Timer: block-synchronization job
2023-08-24T13:46:58.919515585Z ERROR ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-24T13:46:58.917707961Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-24T13:46:58.919691275Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-24T13:47:08.919606355Z otel.kind="server"}: tarpc::server: ReceiveRequest
2023-08-24T13:46:58.919833345Z  INFO ThreadId(04) RPC{rpc.trace_id=00 rpc.deadline=2023-08-24T13:47:08.919606355Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server: BeginRequest
2023-08-24T13:47:08.921023072Z ERROR ThreadId(03) RPC{rpc.trace_id=00 rpc.deadline=2023-08-24T13:47:08.919606355Z otel.kind="server" otel.name="RPC.get_dashboard_overview_data"}: tarpc::server::in_flight_requests: DeadlineExceeded
2023-08-24T13:47:08.921165403Z DEBUG ThreadId(03) tarpc::server::limits::channels_per_key: All channels dropped channel_filter_key=127.0.0.1
2023-08-24T13:48:15.928017863Z DEBUG ThreadId(02) neptune_core::peer_loop: Received peer list req from peer 178.238.174.94:27955
2023-08-24T13:48:15.928092494Z DEBUG ThreadId(02) neptune_core::peer_loop: Responding with: [(139.162.193.206:9798, 64232866295818542391093629608719648170), (146.4.66.241:9798, 50830106355099614853037603722946026806), (178.238.174.94:9798, 65772505080442739472784189864174420785)]
2023-08-24T13:50:07.488957187Z DEBUG ThreadId(03) neptune_core::peer_loop: Received block notification from peer 178.238.174.94:27955
2023-08-24T13:50:07.489334918Z DEBUG ThreadId(03) neptune_core::peer_loop: Got BlockNotification of height 00000000000000002460
dan-da commented 10 months ago

this might help?

dan-da commented 6 months ago

Closed by 1a97899191215b1af385a2ed047829dfa6fe3f29. Note, this was not a classic deadlock, but rather an incompatibility (mis-use) between async crates that led to 100% CPU utilization.

Also fa89d0414f6d95cd7407c67e15e00cdc06b9c121 re-worked the locking so now there is just a single GlobalStateLock, which is an RwLock instead of Mutex. This makes it much easier to reason about locking and eliminates potential out-of-order problems. Further all lock TryAcquire, Acquire, and Release can be logged, (including tokio locks) which greatly aids with debugging if a true deadlock should ever occur.