smite-scenarios: reduce read timeout to 1s#136
Conversation
|
INFO [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO [smite_scenarios::targets::ldk] Starting ldk-node-wrapper...
INFO [smite_scenarios::targets::ldk] LDK identity pubkey: 02a9e7ff9e8a9bda6e3c75725e2965b19facae5a0ae04de8953ab3f4b58080bc8c
INFO [smite_scenarios::targets::ldk] ldk-node-wrapper is ready and synced
INFO [smite_scenarios::targets::ldk] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO [smite::scenarios] Scenario initialized! Executing input...
INFO [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [4.049µs] Executing IR program (28 instructions, 204 input bytes)
DEBUG [smite_scenarios::executor] [115.449µs] SendOpenChannel: 349 bytes
DEBUG [smite_scenarios::executor] [128.888µs] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [7.296746ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [14.696266ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [14.718996ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [17.778817ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [18.073997ms] BroadcastTransaction: txid=14c0721297fd2bc8ca597390f499fdddd94889297e31c3692923972a070a1464
DEBUG [smite_scenarios::executor] [40.387859ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [40.406201ms] SendChannelReady: 77 bytes
DEBUG [smite_scenarios::executor] [45.332039ms] RecvChannelReady: waiting
DEBUG [smite_scenarios::executor] [2.038283883s] RecvChannelReady: received
DEBUG [smite_scenarios::scenarios::ir] [2.038306151s] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [2.078864603s] Target responded with pong
INFO [smite::scenarios] Test case ran successfully!
DEBUG [smite::process] ldk-node-wrapper: dropping running process, attempting shutdown
DEBUG [smite::process] ldk-node-wrapper: sending SIGTERM to process group 53
DEBUG [smite::process] ldk-node-wrapper: exited with exit status: 0
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 7
DEBUG [smite::process] bitcoind: exited with exit status: 0 |
|
Oof. Yeah we will need a different timeout for Although IIRC LDK (and maybe CLN) poll the blockchain at regular intervals while Eclair/LND get notifications on events instead. So perhaps LDK is actually the worse performer for this case. |
|
Yes, Both CLN and LDK poll the blockchain, while Eclair and LND use an event-based approach, so they sync with the blockchain faster LDK has a default polling interval of 2 seconds: https://github.com/lightningdevkit/ldk-node/blob/f2e44fdd21490ff3fa90445d7a28b19cfd020c3d/src/chain/bitcoind.rs#L47 This is also documented in smite: smite/workloads/ldk/src/main.rs Lines 64 to 69 in 4f5f695 For CLN, the default polling interval is 30 seconds, which explains why I’m seeing timeouts while waiting to receive Even though Eclair uses ZMQ, it still delays block processing by 2 seconds, which is why I see a delay before receiving INFO [smite_scenarios::targets::bitcoind] Preserving data directory: /data
INFO [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO [smite_scenarios::targets::eclair] Starting eclair...
INFO [smite_scenarios::targets::eclair] Waiting for eclair to be ready and synced...
INFO [smite_scenarios::targets::eclair] Eclair nodeId: 024b3e358634c64887e9e49f8ff0568d10c050e213b054afc9fcd095b326767e65, blockHeight: 101
INFO [smite_scenarios::targets::eclair] eclair synced (blockheight=101)
INFO [smite_scenarios::targets::eclair] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO [smite::scenarios] Scenario initialized! Executing input...
INFO [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [3.495µs] Executing IR program (28 instructions, 204 input bytes)
DEBUG [smite_scenarios::executor] [80.891µs] SendOpenChannel: 350 bytes
DEBUG [smite_scenarios::executor] [104.037µs] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] skipping unknown message type 39409
DEBUG [smite_scenarios::executor] [59.391399ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [69.111368ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [69.132321ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [94.616098ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [94.891496ms] BroadcastTransaction: txid=23684d02817f282a33c1013429dd4f1437c453a06b3eec8bfc4cecd4e241036e
DEBUG [smite_scenarios::executor] [120.679091ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [120.695703ms] SendChannelReady: 77 bytes
DEBUG [smite_scenarios::executor] [127.944584ms] RecvChannelReady: waiting
DEBUG [smite_scenarios::executor] [2.68874463s] RecvChannelReady: received
DEBUG [smite_scenarios::scenarios::ir] [2.688762338s] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [2.690046323s] Target responded with pong
INFO [smite::scenarios] Test case ran successfully!
DEBUG [smite::process] eclair: dropping running process, attempting shutdown
DEBUG [smite::process] eclair: sending SIGTERM to process group 56
DEBUG [smite::process] eclair: exited with exit status: 143
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 7
DEBUG [smite::process] bitcoind: exited with exit status: 0LND FYI: INFO [smite_scenarios::targets::bitcoind] Preserving data directory: /data
INFO [smite_scenarios::targets::bitcoind] Starting bitcoind...
INFO [smite_scenarios::targets::bitcoind] Waiting for bitcoind to be ready...
INFO [smite_scenarios::targets::bitcoind] bitcoind is ready
INFO [smite_scenarios::targets::lnd] Starting lnd...
INFO [smite_scenarios::targets::lnd] Waiting for lnd to be ready and synced...
INFO [smite_scenarios::targets::lnd] LND identity pubkey: 027eb70169a81541b20cb596a5737863cf60f69b9739b14949267fd54e6161ccd2, blockheight: 101, synced_to_chain: true
INFO [smite_scenarios::targets::lnd] lnd synced (blockheight=101)
INFO [smite_scenarios::targets::lnd] Both daemons are running, ready to fuzz
DEBUG [smite_scenarios::scenarios] Handshake complete, received target init
INFO [smite::scenarios] Scenario initialized! Executing input...
INFO [smite::runners] Reading input from "/input.bin"
DEBUG [smite_scenarios::scenarios::ir] [5.594µs] Executing IR program (28 instructions, 204 input bytes)
DEBUG [smite_scenarios::executor] [105.03µs] SendOpenChannel: 350 bytes
DEBUG [smite_scenarios::executor] [125.858µs] RecvAcceptChannel: waiting
DEBUG [smite_scenarios::executor] [44.688457ms] RecvAcceptChannel: received
DEBUG [smite_scenarios::executor] [54.482137ms] SendFundingCreated: 132 bytes
DEBUG [smite_scenarios::executor] [54.509206ms] RecvFundingSigned: waiting
DEBUG [smite_scenarios::executor] [59.406671ms] RecvFundingSigned: received
DEBUG [smite_scenarios::executor] [59.677332ms] BroadcastTransaction: txid=c764ce8e927775396aae0fd60b3ec2a1d760c51a56f748b1f1e716d0374d13f3
DEBUG [smite_scenarios::executor] [84.190227ms] MineBlocks: mined 8 block(s)
DEBUG [smite_scenarios::executor] [84.207328ms] SendChannelReady: 77 bytes
DEBUG [smite_scenarios::executor] [89.673062ms] RecvChannelReady: waiting
DEBUG [smite_scenarios::executor] [143.007272ms] RecvChannelReady: received
DEBUG [smite_scenarios::scenarios::ir] [143.023805ms] Program executed successfully
DEBUG [smite_scenarios::scenarios::ir] [143.124987ms] Target responded with pong
INFO [smite::scenarios] Test case ran successfully!
DEBUG [smite::process] lnd: dropping running process, attempting shutdown
DEBUG [smite::process] lnd: sending SIGTERM to process group 55
DEBUG [smite::process] lnd: exited with exit status: 0
DEBUG [smite::process] bitcoind: dropping running process, attempting shutdown
DEBUG [smite::process] bitcoind: sending SIGTERM to process group 7
DEBUG [smite::process] bitcoind: exited with exit status: 0 |
This enables the executor to reduce timeouts for messages that are processed quickly and increase timeouts for messages that are processed more slowly.
For current handshake-type flows (open_channel->accept_channel and funding_created->funding_signed), the largest observed response time in the Nyx VM was 444ms under contention. Thus the current timeout value of 5s is overkill and we can safely reduce it to 1s. We keep the timeout for receiving channel_ready at 5s since targets can be slow to poll for new blocks. 5s is enough for every target except CLN, which polls every 30s. In the future we will investigate options for increasing polling frequency for CLN and other targets. Keeping the receive timeout value as low as possible is important for fuzzing efficiency since there are certain situations where a target may ignore one of our messages instead of sending us the response we're waiting for. This was observed in practice with Eclair, which will ignore an open_channel message if it has the same temporary_channel_id as one for which Eclair already sent an accept_channel response.
f2c55fb to
41bc0cb
Compare
|
I've bumped the |
NishantBansal2003
left a comment
There was a problem hiding this comment.
LGTM
I patched CLN to poll every 2s in: #141, and I was able to correctly receive channel_ready within the 5s timeout
CLN has good plugin support. Maybe we could write a plugin that does that. Update: I asked in the CLN telegram group. Christian Decker replied:
|
For current handshake-type flows (
open_channel->accept_channelandfunding_created->funding_signed), the largest observed response time in the Nyx VM was 444ms under contention. Thus the current timeout value of 5s is overkill and we can safely reduce it to 1s.Keeping the receive timeout value as low as possible is important for fuzzing efficiency since there are certain situations where a target may ignore one of our messages instead of sending us the response we're waiting for. This was observed in practice with Eclair, which will ignore an
open_channelmessage if it has the sametemporary_channel_idas one for which Eclair already sent anaccept_channelresponse.Eclair also ignores many other kinds of messages as well:
open_channel2commitment_signedaftertx_abortstfusplice_acktx_ack_rbftx_signaturesI imagine there are also various edge cases where other implementations will also ignore certain messages, so it's important that we don't waste more time waiting than necessary when this happens.