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.

Sign up for GitHub

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

Jump to bottom

IPA integration tests hang sometimes #650

Closed
akoshelev opened this issue May 15, 2023 · 16 comments
Closed

IPA integration tests hang sometimes #650

akoshelev opened this issue May 15, 2023 · 16 comments
Labels
bug Something isn't working

Comments

@akoshelev
Copy link
Collaborator

https://github.com/private-attribution/ipa/actions/runs/4964162687/jobs/8884058950?pr=647
@akoshelev akoshelev added the bug Something isn't working label May 15, 2023
@akoshelev
Copy link
Collaborator Author

Can be reproduced locally too

 while cargo test --test '*' --no-default-features --features "cli web-app real-world-infra test-fixture"; do :; done
    Finished test [unoptimized + debuginfo] target(s) in 1.90s
     Running tests/helper_networks.rs (target/debug/deps/helper_networks-369ed070d66f9396)

running 4 tests
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::net::server: server listening on http://0.0.0.0:3003
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::net::server: server listening on http://0.0.0.0:3004
 INFO ipa::net::server: server listening on http://0.0.0.0:3000
 INFO ipa::net::server: server listening on http://0.0.0.0:3001
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::cli::verbosity: Logging setup at level info
 INFO ipa::net::server: server listening on http://0.0.0.0:3002
 INFO ipa::net::server: server listening on http://0.0.0.0:3005
 INFO ipa::net::server: server listening on https://0.0.0.0:4432
 INFO ipa::net::server: server listening on https://0.0.0.0:4431
 INFO ipa::net::server: server listening on https://0.0.0.0:4430
 INFO ipa::net::server: server listening on https://0.0.0.0:4433
 INFO ipa::net::server: server listening on https://0.0.0.0:4434
 INFO ipa::net::server: server listening on https://0.0.0.0:4435
test http_network ... ok
test https_network ... ok
test http_semi_honest_ipa ... ok
test https_semi_honest_ipa has been running for over 60 seconds

Always IPA tests

@akoshelev
Copy link
Collaborator Author

Running HTTP test in isolation was fine. HTTPS test got hanged pretty quickly. In logs I am not seeing any errors except for TLS handshake. Attaching the logs to this issue if someone wants to take a look

@akoshelev
Copy link
Collaborator Author

ipa-logs.zip

@akoshelev
Copy link
Collaborator Author

akoshelev commented May 15, 2023 •
edited
Loading

I don't like what I am seeing (data race)

 grep "received data for step" ~/Downloads/ipa-logs/*.log | sort
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from B
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc39/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc0/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc1/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h1.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc2/xor2 from C
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/gen_sort_permutation_from_match_keys/sort_keys/bit_permute/bit2 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from C
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc39/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc0/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc1/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h2.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc2/xor1 from A
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/gen_sort_permutation_from_match_keys/sort_keys/bit_permute/bit2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/gen_sort_permutation_from_match_keys/sort_keys/bit_permute/bit4 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/gen_sort_permutation_from_match_keys/sort_keys/bit_permute/bit5 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/gen_sort_permutation_from_match_keys/sort_keys/bit_permute/bit6 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from A
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/ipa/prss_exchange from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc0/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc12/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc15/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc18/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc21/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc24/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc27/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc3/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc30/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc33/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc36/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc39/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc6/mc2/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc0/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc1/xor2 from B
/Users/koshelev/Downloads/ipa-logs/h3.log: INFO ipa::net::server::handlers::query::step: received data for step=protocol/mod_conv_match_key/mc9/mc2/xor2 from B

first grep is from server A, second is from B and the last one is from C.

Good news - PRSS and modulus conversion work. Bad news:

  • helpers moving at different pace
  • helper C appears to be stuck

@akoshelev
Copy link
Collaborator Author

Oof, it is not good. I think I found some evidence that tokio::spawn inside HttpTransport is giving us headache

  grep "ipa::"  /var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/*/*.log | sort | grep -v "received data" | awk '/sending/ && prev ~ /sending/ { print prev } { prev=$0 }'
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit10/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit12/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit13/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit16/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit17/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit4/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit5/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit7/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_least_significant_bits/bit1/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/random_bits/convert_shares/bit25/xor2/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpf3pibC/http/2/ipa-1684199276.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/random_bits/convert_shares/bit26/xor2/C.1: sending

what this command does is prints all steps that were attempted to be sent but never completed

                tracing::info!("step: {:?}/{:?}.1: sending", step, dest);
                let resp_future = self.clients[dest].step(self.identity, query_id, &step, data);
                let resp_future = match resp_future {
                    Ok(f) => f,
                    Err(e) => {
                        tracing::error!("failed to prepare request for step {} to {:?}: {e}", step, dest);
                        return Err(e)
                    }
                };
                tokio::spawn(async move {
                    let poll_f = resp_future
                        .map_err(Into::into)
                        .and_then(MpcHelperClient::resp_ok)
                        .await;

                    match poll_f {
                        Ok(_) => tracing::info!("step: {:?}/{:?}.2 sent", step, dest),
                        Err(e) => {
                            tracing::error!("an error occurred sending {:?} to {:?}: {e}", step, dest);
                            panic!("failed to stream records");
                        }
                    }

@akoshelev
Copy link
Collaborator Author

Another run, same symptoms. If it gets stuck, there is at least one send attempt that did not result in successful send

grep "ipa::"  /var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpoRCbAi/http/*/*.log | sort | grep -v "received data" | awk '/sending/ && prev ~ /sending/ { print prev } { prev=$0 }'
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpoRCbAi/http/2/ipa-1684215311.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit13/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpoRCbAi/http/2/ipa-1684215311.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit17/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpoRCbAi/http/2/ipa-1684215311.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit19/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpoRCbAi/http/2/ipa-1684215311.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/random_bits/convert_shares/bit15/xor2/C.1: sending

@akoshelev
Copy link
Collaborator Author

Next step: I want to take a look at Tokio internals

@akoshelev
Copy link
Collaborator Author

akoshelev commented May 16, 2023 •
edited
Loading

Found some evidence that Tokio is not a problem here.

 tracing::info!("step: {:?}/{:?}.1: sending", step, dest);
                let resp_future = self.clients[dest].step(self.identity, query_id, &step, data);
                let resp_future = match resp_future {
                    Ok(f) => f,
                    Err(e) => {
                        tracing::error!("failed to prepare request for step {} to {:?}: {e}", step, dest);
                        return Err(e)
                    }
                };
                tokio::spawn(async move {
                    tracing::info!("step: {:?}/{:?}.2: scheduled", step, dest);
                    let poll_f = resp_future
                        .map_err(Into::into)
                        .and_then(MpcHelperClient::resp_ok)
                        .await;

                    match poll_f {
                        Ok(_) => tracing::info!("step: {:?}/{:?}.3: sent", step, dest),
                        Err(e) => {
                            tracing::error!("an error occurred sending {:?} to {:?}: {e}", step, dest);
                            panic!("failed to stream records");
                        }
                    }
                        // .expect("failed to stream records");
                });

I am seeing 3 lines for successful sends (sending,scheduled,sent) and 2 lines for unsuccessful

grep "protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit12/C" $FOLDER/http/*/*.log | sed 's/.*step: //'
step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit12/C.1: sending
step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit12/C.2: scheduled

which likely means that polling resp_future gets stuck

                    let poll_f = resp_future
                        .map_err(Into::into)
                        .and_then(MpcHelperClient::resp_ok)
                        .await;

@andyleiserson andyleiserson mentioned this issue May 16, 2023
Open
@akoshelev
Copy link
Collaborator Author

I added some logging inside and_then and it is not being called

                    tracing::info!("step: {:?}/{:?}.2: scheduled", step, dest);
                    let poll_f = resp_future
                        .map_err(Into::into)
                        .and_then(|v| {
                            tracing::info!("step: {:?}/{:?}.3: response received", step, dest);
                            MpcHelperClient::resp_ok(v)
                        })
                        .await;
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmphrNTf7/http/2/ipa-1684259265.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit10/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmphrNTf7/http/2/ipa-1684259265.log: INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit10/C.2: scheduled

@akoshelev
Copy link
Collaborator Author

I strongly suspect that the request gets stuck on the client side (there were similar issues with HTTP2: hyperium/hyper#2419 before), but I can't prove that because of ECC :( I either need to switch to RSA or beg HTTP test to fail in the similar fashion

@akoshelev
Copy link
Collaborator Author

looks like I got it

2023-05-16T19:07:13.639693Z  INFO ipa::cli::verbosity: Logging setup: logging level: trace, output: stderr
test http_semi_honest_ipa has been running for over 60 seconds

@akoshelev
Copy link
Collaborator Author

taking protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit14 as an example

grep $STEP $FOLDER/http/*/*.log
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpBImXXb/http/2/ipa-1684264033.log:2023-05-16T19:07:14.456770Z  INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit14/C.1: sending
/var/folders/n2/wgkrrbd57173j9dvy8bdjcvw0000gn/T/.tmpBImXXb/http/2/ipa-1684264033.log:2023-05-16T19:07:14.456800Z  INFO ipa::net::transport: step: step=protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit14/C.2: scheduled

I am actually seeing an HTTP request for it in wireshark logs

No.	Time	Source	Source port	Destination	Destination port	Protocol	Length	Info
699863	194.737789	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=751 Ack=2464 Win=405824 Len=0 TSval=2360275062 TSecr=1785492200
699865	194.737870	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit14 HTTP/1.1 
699867	194.737918	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=751 Ack=2515 Win=405760 Len=0 TSval=2360275062 TSecr=1785492300

I am also seeing a TCP ack for it (sequence number matches)

699865: Transmission Control Protocol, Src Port: 59710, Dst Port: 3005, Seq: 2464, Ack: 751, Len: 51

but there is no application ack. The source port (59710) was used heavily before failed request though, but each time there was an 200 response

No.	Time	Source	Source port	Destination	Destination port	Protocol	Length	Info
691014	193.936098	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=1 Ack=1 Win=408256 Len=0 TSval=1785491498 TSecr=2360274260
691015	193.936108	127.0.0.1	3005	127.0.0.1	59710	TCP	56	[TCP Window Update] 3005 → 59710 [ACK] Seq=1 Ack=1 Win=408256 Len=0 TSval=2360274260 TSecr=1785491498
691180	193.945093	127.0.0.1	59710	127.0.0.1	3005	HTTP	241	POST /query/0/step/protocol/mod_conv_match_key/mc24/mc2/xor2 HTTP/1.1 
691181	193.945106	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=1 Ack=186 Win=408064 Len=0 TSval=2360274269 TSecr=1785491507
691213	193.947080	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
691215	193.947154	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=186 Ack=76 Win=408192 Len=0 TSval=1785491509 TSecr=2360274271
691311	193.954709	127.0.0.1	59710	127.0.0.1	3005	HTTP	240	POST /query/0/step/protocol/mod_conv_match_key/mc6/mc0/xor2 HTTP/1.1 
691312	193.954718	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=76 Ack=370 Win=407872 Len=0 TSval=2360274279 TSecr=1785491517
691339	193.956291	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
691340	193.956304	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=370 Ack=151 Win=408128 Len=0 TSval=1785491518 TSecr=2360274280
694725	194.275580	127.0.0.1	59710	127.0.0.1	3005	TCP	237	59710 → 3005 [PSH, ACK] Seq=370 Ack=151 Win=408128 Len=181 TSval=1785491838 TSecr=2360274280 [TCP segment of a reassembled PDU]
694726	194.275604	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=151 Ack=551 Win=407744 Len=0 TSval=2360274600 TSecr=1785491838
694743	194.276559	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
694744	194.276585	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=551 Ack=226 Win=408064 Len=0 TSval=1785491839 TSecr=2360274601
694826	194.279677	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/apply_sort_permutation/shuffle_inputs/shuffle1/timestamp HTTP/1.1 
694828	194.279706	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=226 Ack=602 Win=407680 Len=0 TSval=2360274604 TSecr=1785491842
695138	194.298666	127.0.0.1	59710	127.0.0.1	3005	TCP	227	59710 → 3005 [PSH, ACK] Seq=602 Ack=226 Win=408064 Len=171 TSval=1785491861 TSecr=2360274604 [TCP segment of a reassembled PDU]
695140	194.298685	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=226 Ack=773 Win=407488 Len=0 TSval=2360274623 TSecr=1785491861
695167	194.299919	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
695169	194.299948	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=773 Ack=301 Win=408000 Len=0 TSval=1785491862 TSecr=2360274624
695328	194.315838	127.0.0.1	59710	127.0.0.1	3005	HTTP	76	POST /query/0/step/protocol/binary_validator/apply_sort_permutation/shuffle_inputs/shuffle1/elem3 HTTP/1.1 
695329	194.315864	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=301 Ack=793 Win=407488 Len=0 TSval=2360274640 TSecr=1785491878
695355	194.317008	127.0.0.1	59710	127.0.0.1	3005	HTTP	248	POST /query/0/step/protocol/binary_validator/apply_sort_permutation/shuffle_inputs/shuffle1/elem28 HTTP/1.1 
695356	194.317025	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=301 Ack=985 Win=407296 Len=0 TSval=2360274641 TSecr=1785491879
695418	194.319588	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
695419	194.319613	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=985 Ack=376 Win=407872 Len=0 TSval=1785491881 TSecr=2360274643
696349	194.376553	127.0.0.1	59710	127.0.0.1	3005	TCP	200	59710 → 3005 [PSH, ACK] Seq=985 Ack=376 Win=407872 Len=144 TSval=1785491939 TSecr=2360274643 [TCP segment of a reassembled PDU]
696350	194.376580	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=376 Ack=1129 Win=407168 Len=0 TSval=2360274701 TSecr=1785491939
696419	194.379829	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
696420	194.379853	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=1129 Ack=451 Win=407808 Len=0 TSval=1785491942 TSecr=2360274704
696597	194.388829	127.0.0.1	59710	127.0.0.1	3005	HTTP	75	POST /query/0/step/protocol/binary_validator/compute_helper_bits/bit11 HTTP/1.1 
696600	194.388856	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=451 Ack=1148 Win=407104 Len=0 TSval=2360274713 TSecr=1785491951
697575	194.459058	127.0.0.1	59710	127.0.0.1	3005	TCP	279	59710 → 3005 [PSH, ACK] Seq=1148 Ack=451 Win=407808 Len=223 TSval=1785492021 TSecr=2360274713 [TCP segment of a reassembled PDU]
697576	194.459083	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=451 Ack=1371 Win=406912 Len=0 TSval=2360274783 TSecr=1785492021
697593	194.460428	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
697594	194.460470	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=1371 Ack=526 Win=407744 Len=0 TSval=1785492022 TSecr=2360274784
697764	194.473088	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/random_bits/convert_shares/bit19/xor2 HTTP/1.1 
697765	194.473112	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=526 Ack=1422 Win=406848 Len=0 TSval=2360274797 TSecr=1785492035
697783	194.473742	127.0.0.1	59710	127.0.0.1	3005	TCP	306	59710 → 3005 [PSH, ACK] Seq=1422 Ack=526 Win=407744 Len=250 TSval=1785492035 TSecr=2360274797 [TCP segment of a reassembled PDU]
697784	194.473769	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=526 Ack=1672 Win=406592 Len=0 TSval=2360274797 TSecr=1785492035
697791	194.474170	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/user_capping/report_level_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_least_significant_bits/bit0 HTTP/1.1 
697792	194.474195	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=526 Ack=1723 Win=406528 Len=0 TSval=2360274798 TSecr=1785492036
697847	194.476672	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
697848	194.476698	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=1723 Ack=601 Win=407680 Len=0 TSval=1785492039 TSecr=2360274801
699514	194.618058	127.0.0.1	59710	127.0.0.1	3005	TCP	258	59710 → 3005 [PSH, ACK] Seq=1723 Ack=601 Win=407680 Len=202 TSval=1785492180 TSecr=2360274801 [TCP segment of a reassembled PDU]
699515	194.618084	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=601 Ack=1925 Win=406336 Len=0 TSval=2360274942 TSecr=1785492180
699593	194.623827	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
699594	194.623855	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=1925 Ack=676 Win=407616 Len=0 TSval=1785492185 TSecr=2360274947
699728	194.633200	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/random_bits/convert_shares/bit17/xor2 HTTP/1.1 
699729	194.633227	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=676 Ack=1976 Win=406272 Len=0 TSval=2360274957 TSecr=1785492195
699743	194.633921	127.0.0.1	59710	127.0.0.1	3005	TCP	274	59710 → 3005 [PSH, ACK] Seq=1976 Ack=676 Win=407616 Len=218 TSval=1785492196 TSecr=2360274957 [TCP segment of a reassembled PDU]
699744	194.633949	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=676 Ack=2194 Win=406080 Len=0 TSval=2360274958 TSecr=1785492196
699749	194.634274	127.0.0.1	59710	127.0.0.1	3005	HTTP	107	POST /query/0/step/protocol/after_convert_all_bits/user_capping/random_bits_for_comparison/is_p_less_than_b/check_trimmed/check_if_all_ones/bit4 HTTP/1.1 
699751	194.634312	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=676 Ack=2245 Win=406016 Len=0 TSval=2360274958 TSecr=1785492196
699786	194.635610	127.0.0.1	3005	127.0.0.1	59710	HTTP	131	HTTP/1.1 200 OK 
699787	194.635637	127.0.0.1	59710	127.0.0.1	3005	TCP	56	59710 → 3005 [ACK] Seq=2245 Ack=751 Win=407488 Len=0 TSval=1785492197 TSecr=2360274959
699829	194.638389	127.0.0.1	59710	127.0.0.1	3005	TCP	275	59710 → 3005 [PSH, ACK] Seq=2245 Ack=751 Win=407488 Len=219 TSval=1785492200 TSecr=2360274959 [TCP segment of a reassembled PDU]
699863	194.737789	127.0.0.1	3005	127.0.0.1	59710	TCP	56	3005 → 59710 [ACK] Seq=751 Ack=2464 Win=405824 Len=0 TSval=2360275062 TSecr=1785492200

@akoshelev
Copy link
Collaborator Author

akoshelev commented May 17, 2023 •
edited
Loading

for the sake of experiment, I switched to http2 only on the client side

    pub fn new_with_connector(addr: Uri, connector: HttpsConnector<HttpConnector>) -> Self {
        let client = Client::builder()
            .http2_only(true).build(connector);

works with no issues :( 100 runs and counting without any failures. both HTTP and HTTPS tests pass

@martinthomson
Copy link
Member

martinthomson commented May 17, 2023 •
edited
Loading

I had a feeling that this might be connection-management related. It might pay to land that, but you should make sure that the number of concurrent streams is adequate when we do that.

I hate not understanding a problem better, but we have lots to do.

https://docs.rs/hyper/latest/hyper/server/struct.Builder.html#method.http2_max_concurrent_streams

@akoshelev
Copy link
Collaborator Author

All right I think I got it now. What we are observing here is another occurrence of hyperium/hyper#2312.

This client configuration

        let client = Client::builder()
            .pool_max_idle_per_host(0)
            .build(connector);

fixes the issue, but it is not sustainable in our setting - integration tests would need to open ~24k TCP connections and that is both slow (handshakes everywhere) and unreliable on a single machine - I am getting panics.

Here is what I am going to do

@akoshelev akoshelev mentioned this issue May 18, 2023
Merged
@akoshelev
Copy link
Collaborator Author

I am going to close this issue because we've mitigated the problem - but will keep an eye on hyperium/hyper#2312

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@martinthomson @akoshelev