Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TP v.0.1.14 takes a lot to complete handshakes after the first one #80

Open
1 task done
GitGab19 opened this issue Feb 21, 2025 · 12 comments
Open
1 task done

TP v.0.1.14 takes a lot to complete handshakes after the first one #80

GitGab19 opened this issue Feb 21, 2025 · 12 comments
Labels

Comments

@GitGab19
Copy link

Is there an existing issue for this?

  • I have searched the existing issues

Current behaviour

I tested v.0.1.14 together with my corresponding PR on SRI: stratum-mining/stratum#1456, to test the new CoinbaseOutputConstraints message.

Using just the Pool, it's easy to see that the first time it connects to the TP, everything is fine.
But if I restart the Pool, the second handshake takes a lot of time to finish, and sometimes it doesn't finish at all.

Expected behaviour

As with previous versions, the handshakes should be completed quickly

Steps to reproduce

Run the latest version of TP (v.0.1.14) and checkout my PR on SRI: stratum-mining/stratum#1456.

Then run the Pool role for the first time, kill it, and then start it again.

Relevant log output

No response

How did you obtain Bitcoin Core

Compiled from source

What version of Bitcoin Core are you using?

TP v.0.1.14

Operating system and version

Mac OS 13.0.1

Machine specifications

No response

@GitGab19 GitGab19 added the bug label Feb 21, 2025
@GitGab19
Copy link
Author

TP logs:

2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> HANDSHAKE_STEP_1
2025-02-21T13:43:27Z [sv2:trace] New client id=0 connected
2025-02-21T13:43:27Z [sv2:trace] Read their ephemeral key
2025-02-21T13:43:27Z [sv2:trace] Mix hash: aee30c408e6e08f32da5df2fd8b3ae829e578c2fd87072c2f60857cb227c5c86
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> HANDSHAKE_STEP_2
2025-02-21T13:43:27Z [sv2:trace] Generate ephemeral key
2025-02-21T13:43:27Z [sv2:trace] Write our ephemeral key
2025-02-21T13:43:27Z [sv2:trace] Mix hash: ef96fb480d118efd1036a52be80fbef56ad2bd9050d8843d71ce972269eac3f7
2025-02-21T13:43:27Z [sv2:trace] Perform ECDH with the remote ephemeral key
2025-02-21T13:43:27Z [sv2:trace] Mix key with ECDH result: ephemeral ours -- remote ephemeral
2025-02-21T13:43:27Z [sv2:trace] Chaining key: e46b592e70bf11f16b037c3e988ddceb29f62e2aa118aef0a267da1e7298e7df
2025-02-21T13:43:27Z [sv2:trace] Encrypt and write our static key
2025-02-21T13:43:27Z [sv2:trace] Mix hash: 7abbe5571893540e58d01c2a6681432217f32548a9b5f22bc5d386892ee75ca3
2025-02-21T13:43:27Z [sv2:trace] Perform ECDH between our static and remote ephemeral key
2025-02-21T13:43:27Z [sv2:trace] ECDH result: f19aeb404eb4bd7257edbeef7e11db4d8eb139dfd66ad554fa5bfee543a3fa7e
2025-02-21T13:43:27Z [sv2:trace] Mix key with ECDH result: static ours -- remote ephemeral
2025-02-21T13:43:27Z [sv2:trace] Chaining key: 195b2228e735e9b2a51045a4580591a7568408b2c6546cee9fad62b744256f56
2025-02-21T13:43:27Z [sv2:trace] Encrypt certificate: 0000ec74b867ffffffff4b9007876eb58b793625c94a93d0042406927734bb17e58d503cdcbc5bf3e5c44143ad2d52b7b6d42fac5d652afc1b8ad979e97d49524fd1db70caa4e35e27f9
2025-02-21T13:43:27Z [sv2:trace] Mix hash: 1c972ed9ffe3e1e8332f678363438ee75dc427ff7c3b4f458d5bedf63af2e576
2025-02-21T13:43:27Z [sv2:trace] Noise session send state -> READY
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:27Z [sv2:trace] Send 234 bytes to client id=0
2025-02-21T13:43:27Z [sv2:trace] Header: 000000190000
2025-02-21T13:43:27Z [sv2:trace] Expecting 25 bytes payload (plain)
2025-02-21T13:43:27Z [sv2:trace] Payload: 020200020000000000093132372e302e302e31fa2000000000
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> APP_READY
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:27Z [sv2] Received 0x00 SetupConnection from client id=0
2025-02-21T13:43:27Z [sv2] Send 0x01 SetupConnection.Success to client id=0
2025-02-21T13:43:27Z [sv2:trace] Header: 000001060000
2025-02-21T13:43:27Z [sv2:trace] Send 44 bytes to client id=0
2025-02-21T13:43:27Z [sv2:trace] Header: 000070060000
2025-02-21T13:43:27Z [sv2:trace] Expecting 6 bytes payload (plain)
2025-02-21T13:43:27Z [sv2:trace] Payload: 010000000000
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> APP_READY
2025-02-21T13:43:27Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:27Z [sv2] Received 0x70 CoinbaseOutputConstraints from client id=0
2025-02-21T13:43:27Z [sv2] coinbase_output_max_additional_size=1 bytes
2025-02-21T13:43:27Z CreateNewBlock(): block weight: 507539 txs: 339 fees: 405641 sigops 489
2025-02-21T13:43:27Z [sv2:trace] Assemble template: 6.31ms
2025-02-21T13:43:27Z [sv2] Send 0x71 NewTemplate id=1 future=1 to client id=0
2025-02-21T13:43:27Z [sv2] Send 0x72 SetNewPrevHash to client id=0
2025-02-21T13:43:28Z [sv2:trace] Header: 0000717d0100
2025-02-21T13:43:28Z [sv2:trace] Send 419 bytes to client id=0
2025-02-21T13:43:28Z [sv2:trace] Header: 000072500000
2025-02-21T13:43:28Z [sv2:trace] Send 118 bytes to client id=0
2025-02-21T13:43:34Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=2
2025-02-21T13:43:53Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=3
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> HANDSHAKE_STEP_1
2025-02-21T13:43:53Z [sv2:trace] New client id=1 connected
2025-02-21T13:43:53Z [sv2:trace] Read their ephemeral key
2025-02-21T13:43:53Z [sv2:trace] Mix hash: f88d060c347c5b1af767ab5a9aabda7fe4008818bdf4b94c54c15a8b0e3cd25d
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> HANDSHAKE_STEP_2
2025-02-21T13:43:53Z [sv2:trace] Generate ephemeral key
2025-02-21T13:43:53Z [sv2:trace] Write our ephemeral key
2025-02-21T13:43:53Z [sv2:trace] Mix hash: 3f73d728c6f56fc523e618659cc72931bb6cc08eb29d621b070d029dde55f19b
2025-02-21T13:43:53Z [sv2:trace] Perform ECDH with the remote ephemeral key
2025-02-21T13:43:53Z [sv2:trace] Mix key with ECDH result: ephemeral ours -- remote ephemeral
2025-02-21T13:43:53Z [sv2:trace] Chaining key: ed2c46062d87b44e0d5dfefbd9a157a929a170e2edbceb94d12c4d345ecb7f8f
2025-02-21T13:43:53Z [sv2:trace] Encrypt and write our static key
2025-02-21T13:43:53Z [sv2:trace] Mix hash: be8677d057ca0650bd09feef0feb5fac9f9e5f89b03d1d3a2ba664aabc26a595
2025-02-21T13:43:53Z [sv2:trace] Perform ECDH between our static and remote ephemeral key
2025-02-21T13:43:53Z [sv2:trace] ECDH result: 01609c164e7edf40cce50ea5f193387ff6a4568eeac0338b7ec28fe54f01c5dc
2025-02-21T13:43:53Z [sv2:trace] Mix key with ECDH result: static ours -- remote ephemeral
2025-02-21T13:43:53Z [sv2:trace] Chaining key: 6e2fd207dacc59e99e439157aeda716db5607cbde6870ea4ba8ab1aa7b94f702
2025-02-21T13:43:53Z [sv2:trace] Encrypt certificate: 0000ec74b867ffffffff4b9007876eb58b793625c94a93d0042406927734bb17e58d503cdcbc5bf3e5c44143ad2d52b7b6d42fac5d652afc1b8ad979e97d49524fd1db70caa4e35e27f9
2025-02-21T13:43:53Z [sv2:trace] Mix hash: 25c7dfdf5d34177f2c8a54ec6580106fb7af5ba0f6f070a3ab52d7ee4cabbbb2
2025-02-21T13:43:53Z [sv2:trace] Noise session send state -> READY
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:53Z [sv2:trace] Send 234 bytes to client id=1
2025-02-21T13:43:53Z [sv2:trace] Header: 000000190000
2025-02-21T13:43:53Z [sv2:trace] Expecting 25 bytes payload (plain)
2025-02-21T13:43:53Z [sv2:trace] Payload: 020200020000000000093132372e302e302e31fa2000000000
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> APP_READY
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:53Z [sv2] Received 0x00 SetupConnection from client id=1
2025-02-21T13:43:53Z [sv2] Send 0x01 SetupConnection.Success to client id=1
2025-02-21T13:43:53Z [sv2:trace] Header: 000001060000
2025-02-21T13:43:53Z [sv2:trace] Send 44 bytes to client id=1
2025-02-21T13:43:53Z [sv2:trace] Header: 000070060000
2025-02-21T13:43:53Z [sv2:trace] Expecting 6 bytes payload (plain)
2025-02-21T13:43:53Z [sv2:trace] Payload: 010000000000
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> APP_READY
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> APP
2025-02-21T13:43:53Z [sv2] Received 0x70 CoinbaseOutputConstraints from client id=1
2025-02-21T13:43:53Z [sv2] coinbase_output_max_additional_size=1 bytes
2025-02-21T13:43:54Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=4
2025-02-21T13:43:54Z CreateNewBlock(): block weight: 586614 txs: 397 fees: 463431 sigops 504
2025-02-21T13:43:54Z [sv2:trace] Assemble template: 6.54ms
2025-02-21T13:43:54Z [sv2] Send 0x71 NewTemplate id=2 future=1 to client id=1
2025-02-21T13:43:54Z [sv2] Send 0x72 SetNewPrevHash to client id=1
2025-02-21T13:43:55Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=5
2025-02-21T13:43:55Z CreateNewBlock(): block weight: 586614 txs: 397 fees: 463431 sigops 504
2025-02-21T13:43:56Z [sv2:trace] Header: 0000717d0100
2025-02-21T13:43:56Z [sv2:trace] Send 419 bytes to client id=1
2025-02-21T13:43:56Z [sv2:trace] Header: 000072500000
2025-02-21T13:43:56Z [sv2:trace] Send 118 bytes to client id=1
2025-02-21T13:43:57Z P2P peers available. Skipped DNS seeding.
2025-02-21T13:43:57Z dnsseed thread exit
2025-02-21T13:44:02Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=6
2025-02-21T13:44:03Z New outbound-full-relay v2 peer connected: 

Pool logs:

2025-02-21T13:43:27.685447Z  INFO pool_sv2::lib::template_receiver: Connected to template distribution server at 127.0.0.1:8442
2025-02-21T13:43:27.691721Z  INFO roles_logic_sv2::handlers::common: Received SetupConnectionSuccess: version=2, flags=0
2025-02-21T13:43:27.691961Z  INFO pool_sv2::lib::mining_pool: PUB KEY: Ok([TxOut { value: 0 SAT, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ebe1b7dcc293ccaa0ee743a86f89df8258c208fc) }])
2025-02-21T13:43:27.692817Z  INFO pool_sv2::lib::mining_pool: Starting up pool listener
2025-02-21T13:43:27.693067Z  INFO pool_sv2::lib::mining_pool: Listening for encrypted connection on: 0.0.0.0:34254
2025-02-21T13:43:28.820473Z  INFO roles_logic_sv2::handlers::template_distribution: Received NewTemplate with id: 1, is future: true
2025-02-21T13:43:28.821240Z  INFO roles_logic_sv2::handlers::template_distribution: Received SetNewPrevHash for template: 1
^C2025-02-21T13:43:34.892080Z  INFO pool_sv2::lib: Interrupt received

Pool restarted:

2025-02-21T13:43:35.924830Z  INFO pool_sv2::lib::template_receiver: Connected to template distribution server at 127.0.0.1:8442
2025-02-21T13:43:53.876409Z  INFO roles_logic_sv2::handlers::common: Received SetupConnectionSuccess: version=2, flags=0
2025-02-21T13:43:53.876609Z  INFO pool_sv2::lib::mining_pool: PUB KEY: Ok([TxOut { value: 0 SAT, script_pubkey: Script(OP_0 OP_PUSHBYTES_20 ebe1b7dcc293ccaa0ee743a86f89df8258c208fc) }])
2025-02-21T13:43:53.877611Z  INFO pool_sv2::lib::mining_pool: Starting up pool listener
2025-02-21T13:43:53.877878Z  INFO pool_sv2::lib::mining_pool: Listening for encrypted connection on: 0.0.0.0:34254

@GitGab19
Copy link
Author

@Sjors as you can see from the logs, the second time I run the Pool, it's at 2025-02-21T13:43:35.924830Z.

But from the TP logs, it's not possible to see the second noise connection request until 2025-02-21T13:43:53Z

So that demonstrates how the Pool gets stuck for about 18 seconds

@Sjors
Copy link
Owner

Sjors commented Feb 21, 2025

This is probably not related to the changes in CoinbaseOutputConstraints, since the delay happens long before that message is sent.

More likely the problem is that once the TP has a connection, it's (partially) blocked from listening to new connections. This might be tricky to debug. I'm going to try the laziest solution first, namely to update the sv2 branch with all the latest verions of my all my pull requests.

I'll ping you when that's done so you can test it. If it works I'll tag a new release, otherwise I'll investigate more but it might be two weeks before I get to that.

@Sjors
Copy link
Owner

Sjors commented Feb 21, 2025

@GitGab19 can you give the sv2 branch a try? #68

I'll try to do some local testing as well later today.

@Sjors
Copy link
Owner

Sjors commented Feb 21, 2025

I can't reproduce this with the latest sjors/sv2 branch at 5fe5296.

But also not with the sv2-tp-0.1.14 tag.

Both compiled from source as a debug build: cmake -B build -DCMAKE_BUILD_TYPE=Debug

For the pool I used your PR at c76a161cfe6e7ea6b5b2f11381a6eb6ebb62035b. Both on the same machine, using SRI signet. I didn't mine.

Tested on (Apple Silicon) macOS 15.3.1

Let me know how it goes on your end...

Do you get the same issue when you keep the pool connected, and then connect from another role? If not, then maybe the problem is related to the disconnection.

Also, did you test whether v.0.1.13 has the same issue? (maybe just dropping the CoinbaseOutputConstraints change, keeping everything else the same for SRI)

@Sjors
Copy link
Owner

Sjors commented Feb 21, 2025

It's also a good idea to wipe the build directory if you switch between versions, since there were a lot of build system changes in Bitcoin Core.

@GitGab19
Copy link
Author

Sorry I was stuck in other stuff during last days. I just compiled your last commit (5fe5296) and tested again.

Unfortunately I still get the same behaviour..

Do you get the same issue when you keep the pool connected, and then connect from another role? If not, then maybe the problem is related to the disconnection.

I get the same issue also if I connect a JDC to the TP after the Pool.

Also, did you test whether v.0.1.13 has the same issue?

v.0.1.13 doesn't have this issue at all, I tested it last week and everything was fine.

@Sjors
Copy link
Owner

Sjors commented Feb 27, 2025

Thanks for the update. Difficult to debug until I can reproduce...

I noticed you're using macOS 13, is that an Intel machine? I'll try that later, maybe it helps in reproducing.

How are you building and compiling both Bitcoin Core and the pool role? Are you running them straight from the command line terminal, or some Docker like setup?

Have you tried on a linux machine?

@GitGab19
Copy link
Author

GitGab19 commented Feb 27, 2025

I noticed you're using macOS 13, is that an Intel machine? I'll try that later, maybe it helps in reproducing.

Yes, it is.

I'm running everything from the command line.
I'm getting the same behavior also on ubuntu btw

@Sjors
Copy link
Owner

Sjors commented Feb 27, 2025

How are you building and compiling both Bitcoin Core and the pool role?

Maybe there's detail there that I'm doing different.

Also, are you using the SRI signet, or testnet4 or mainnet?

@GitGab19
Copy link
Author

GitGab19 commented Feb 28, 2025

How are you building and compiling both Bitcoin Core and the pool role?

  • cmake -B build -DENABLE_WALLET=OFF + cmake --build build -j$(sysctl -n hw.ncpu) to build and compile Core.
  • cargo run -- -c config-examples/pool-config-local-tp-example.toml for the Pool (on the PR #1456 branch)

Also, are you using the SRI signet, or testnet4 or mainnet?

I'm using testnet4.

On ubuntu I just used the binary provided by you btw, I haven't tried to compile it from latest commit.

@Sjors
Copy link
Owner

Sjors commented Feb 28, 2025

I haven't tried to compile it from latest commit.

This would be useful for comparison.

Can you try again with more verbose logging: -debug=1 -loglevel=trace -logthreadnames -logtimemicros

When building, can you add -DCMAKE_BUILD_TYPE=Debug?

I'd also like to know if this only happens when you disconnect and reconnect, or if it also happens if you get a second connection (e.g. from a JDC).

2025-02-21T13:43:28Z [sv2:trace] Send 118 bytes to client id=0
2025-02-21T13:43:34Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=2
2025-02-21T13:43:53Z New outbound-full-relay v2 peer connected: version: 70016, blocks=71075, peer=3
2025-02-21T13:43:53Z [sv2:trace] Noise session receive state -> HANDSHAKE_STEP_1
2025-02-21T13:43:53Z [sv2:trace] New client id=1 connected

The timing here suggests that our main thread is blocked, and then suddenly becomes available again and serves both a normal peer (p2p) and your pool (sv2). cc @vasild


I can't reproduce with testnet4 either, but will try on an Intel Mac next week.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants