Breakdown reveal aggregation test hangs sometimes

akoshelev commented 1 week ago

we can try to reproduce it with this seed: 4039690703696284216 https://github.com/private-attribution/ipa/actions/runs/11018449181/job/30598750956?pr=1307

---- protocol::ipa_prf::aggregation::breakdown_reveal::tests::semi_honest_happy_path stdout ----
TestWorld random seed 4039690703696284216
2024-09-24T17:06:13.580916Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:06:13.580924Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.580951Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:06:13.580955Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.580975Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:06:13.580980Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.581003Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.86µs time.idle=74.8µs
2024-09-24T17:06:13.581008Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=26.2µs time.idle=67.2µs
2024-09-24T17:06:13.581702Z  INFO transport_loop{id=A}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.581739Z  INFO transport_loop{id=B}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.581767Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=912ns time.idle=809µs
2024-09-24T17:06:13.581776Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=20.1µs time.idle=806µs
2024-09-24T17:06:13.581786Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=632ns time.idle=802µs
2024-09-24T17:06:13.581791Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=35.5µs time.idle=780µs
2024-09-24T17:06:13.581798Z  INFO transport_loop{id=C}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:06:13.582789Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:06:13.582814Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:06:13.583134Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:06:13.583140Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:06:13.583319Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:06:13.583324Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:06:13.583636Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1153. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:06:13.583647Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=318µs time.idle=4.71µs
2024-09-24T17:06:13.583654Z  INFO breakdown_reveal_aggregation{total=1150}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:06:13.585788Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1153. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:06:13.585797Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=499µs time.idle=2.16ms
2024-09-24T17:06:13.585804Z  INFO breakdown_reveal_aggregation{total=1150}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:06:13.587743Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1153. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:06:13.587765Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:07:14.794087Z  INFO breakdown_reveal_aggregation{total=1150}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=21.8s time.idle=39.4s
2024-09-24T17:07:14.794107Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:07:14.820325Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=18.2s time.idle=43.0s
2024-09-24T17:07:14.820339Z  INFO breakdown_reveal_aggregation{total=1150}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=14.9ms time.idle=61.2s
2024-09-24T17:07:14.820351Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:07:14.865388Z  INFO breakdown_reveal_aggregation{total=1150}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=25.2s time.idle=36.1s
2024-09-24T17:07:14.865409Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:07:56.684429Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=15.6s time.idle=26.2s
2024-09-24T17:07:56.684451Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:07:56.701272Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=16.2s time.idle=25.7s
2024-09-24T17:07:56.701293Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:07:56.706846Z  INFO breakdown_reveal_aggregation{total=1150}:reveal_breakdowns{total=2303}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=15.7s time.idle=26.2s
2024-09-24T17:07:56.706861Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:08:04.742277Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.69s time.idle=5.34s
2024-09-24T17:08:04.742299Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=39.9s time.idle=71.2s
2024-09-24T17:08:04.763997Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.75s time.idle=5.33s
2024-09-24T17:08:04.764016Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=35.9s time.idle=75.2s
2024-09-24T17:08:04.764987Z  INFO breakdown_reveal_aggregation{total=1150}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.75s time.idle=5.32s
2024-09-24T17:08:04.764996Z  INFO breakdown_reveal_aggregation{total=1150}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=43.5s time.idle=67.7s
2024-09-24T17:08:04.766215Z  INFO transport_loop{id=A}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.37s time.idle=110s
2024-09-24T17:08:04.766319Z  INFO transport_loop{id=B}: ipa_core::helpers::transport::in_memory::transport: close time.busy=674ms time.idle=111s
2024-09-24T17:08:04.766387Z  INFO transport_loop{id=C}: ipa_core::helpers::transport::in_memory::transport: close time.busy=323ms time.idle=111s
TestWorld random seed 14957150541626972876
2024-09-24T17:08:04.777080Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:08:04.777092Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.777105Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:08:04.777109Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.777116Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:08:04.777119Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.777131Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=2.81µs time.idle=18.5µs
2024-09-24T17:08:04.777138Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=5.77µs time.idle=27.6µs
2024-09-24T17:08:04.777[146](https://github.com/private-attribution/ipa/actions/runs/11018449181/job/30598750956?pr=1307#step:8:147)Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.31µs time.idle=52.6µs
2024-09-24T17:08:04.777150Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=13.5µs time.idle=58.2µs
2024-09-24T17:08:04.777877Z  INFO transport_loop{id=A}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.777885Z  INFO transport_loop{id=B}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.777891Z  INFO transport_loop{id=C}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:08:04.778480Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:08:04.778488Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:08:04.778501Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.44µs time.idle=1.38ms
2024-09-24T17:08:04.778508Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=36.2µs time.idle=1.36ms
2024-09-24T17:08:04.778779Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:08:04.778785Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:08:04.778897Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:08:04.778903Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:08:04.779124Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1152. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:08:04.779134Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=227µs time.idle=4.80µs
2024-09-24T17:08:04.779141Z  INFO breakdown_reveal_aggregation{total=1114}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:08:04.780234Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1152. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:08:04.780243Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=401µs time.idle=1.06ms
2024-09-24T17:08:04.780252Z  INFO breakdown_reveal_aggregation{total=1114}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:08:04.781293Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1152. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:08:04.781303Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:09:05.027730Z  INFO breakdown_reveal_aggregation{total=1114}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=21.3s time.idle=38.9s
2024-09-24T17:09:05.027751Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:05.086736Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=18.0s time.idle=42.3s
2024-09-24T17:09:05.086752Z  INFO breakdown_reveal_aggregation{total=1114}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=11.8ms time.idle=60.3s
2024-09-24T17:09:05.086767Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:05.136592Z  INFO breakdown_reveal_aggregation{total=1114}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=24.7s time.idle=35.7s
2024-09-24T17:09:05.136615Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:42.690847Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:09:42.692215Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=14.0s time.idle=23.7s
2024-09-24T17:09:42.697750Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=14.6s time.idle=23.0s
2024-09-24T17:09:42.697768Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:09:42.702638Z  INFO breakdown_reveal_aggregation{total=1114}:reveal_breakdowns{total=2266}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=14.6s time.idle=23.1s
2024-09-24T17:09:42.702652Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:09:50.254270Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.55s time.idle=5.01s
2024-09-24T17:09:50.254288Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=33.9s time.idle=71.6s
2024-09-24T17:09:50.255087Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.53s time.idle=5.02s
2024-09-24T17:09:50.255095Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=37.8s time.idle=67.7s
2024-09-24T17:09:50.255237Z  INFO breakdown_reveal_aggregation{total=1114}:aggregate_values{num_rows=110}: ipa_core::protocol::ipa_prf::aggregation: close time.busy=2.51s time.idle=5.05s
2024-09-24T17:09:50.255245Z  INFO breakdown_reveal_aggregation{total=1114}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=41.3s time.idle=64.2s
2024-09-24T17:09:50.256409Z  INFO transport_loop{id=A}: ipa_core::helpers::transport::in_memory::transport: close time.busy=582ms time.idle=105s
2024-09-24T17:09:50.256491Z  INFO transport_loop{id=B}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.05s time.idle=104s
2024-09-24T17:09:50.256551Z  INFO transport_loop{id=C}: ipa_core::helpers::transport::in_memory::transport: close time.busy=646ms time.idle=105s
TestWorld random seed 7042706895729876975
2024-09-24T17:09:50.266869Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:09:50.266880Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.266912Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:09:50.266917Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.266944Z  INFO {h=A}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=2.96µs time.idle=60.5µs
2024-09-24T17:09:50.266951Z  INFO {h=A}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=19.6µs time.idle=63.6µs
2024-09-24T17:09:50.266961Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: new
2024-09-24T17:09:50.266965Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.267676Z  INFO transport_loop{id=A}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.267684Z  INFO {h=C}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.66µs time.idle=717µs
2024-09-24T17:09:50.267690Z  INFO {h=C}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=8.48µs time.idle=720µs
2024-09-24T17:09:50.267696Z  INFO {h=B}:transport_loop{id=ShardIndex(0)}: ipa_core::helpers::transport::in_memory::transport: close time.busy=1.27µs time.idle=778µs
2024-09-24T17:09:50.267701Z  INFO {h=B}: ipa_core::helpers::transport::in_memory::sharding: close time.busy=41.8µs time.idle=747µs
2024-09-24T17:09:50.267709Z  INFO transport_loop{id=B}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.267717Z  INFO transport_loop{id=C}: ipa_core::helpers::transport::in_memory::transport: new
2024-09-24T17:09:50.268421Z  INFO breakdown_reveal_aggregation{total=[147](https://github.com/private-attribution/ipa/actions/runs/11018449181/job/30598750956?pr=1307#step:8:148)4}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:50.268437Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:09:50.268697Z  INFO breakdown_reveal_aggregation{total=1474}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:50.268703Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:09:50.268824Z  INFO breakdown_reveal_aggregation{total=1474}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:09:50.268829Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: new
2024-09-24T17:09:50.269050Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1[148](https://github.com/private-attribution/ipa/actions/runs/11018449181/job/30598750956?pr=1307#step:8:149). Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:09:50.269060Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=226µs time.idle=4.09µs
2024-09-24T17:09:50.269066Z  INFO breakdown_reveal_aggregation{total=1474}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:09:50.270289Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1148. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:09:50.270299Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=323µs time.idle=1.27ms
2024-09-24T17:09:50.270307Z  INFO breakdown_reveal_aggregation{total=1474}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:09:50.271037Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: Total number of padding records added: 1148. Padding Parameters: PaddingParameters { aggregation_padding: Parameters { aggregation_epsilon: 5.0, aggregation_delta: 1e-6, aggregation_padding_sensitivity: 10 }, oprf_padding: Parameters { oprf_epsilon: 5.0, oprf_delta: 1e-6, matchkey_cardinality_cap: 10, oprf_padding_sensitivity: 2 } }
2024-09-24T17:09:50.271047Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:11:11.848035Z  INFO breakdown_reveal_aggregation{total=1474}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=29.2s time.idle=52.3s
2024-09-24T17:11:11.848058Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:11:11.895522Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=23.5s time.idle=58.2s
2024-09-24T17:11:11.895538Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding: ipa_core::protocol::ipa_prf::oprf_padding: close time.busy=389ms time.idle=81.2s
2024-09-24T17:11:11.895550Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:11:11.928096Z  INFO breakdown_reveal_aggregation{total=1474}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=33.9s time.idle=47.8s
2024-09-24T17:11:11.928115Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:12:05.641235Z  INFO breakdown_reveal_aggregation{total=1474}:aggregate_values{num_rows=118}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:12:05.661013Z  INFO breakdown_reveal_aggregation{total=1474}:aggregate_values{num_rows=118}: ipa_core::protocol::ipa_prf::aggregation: new
2024-09-24T17:12:05.669227Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=19.8s time.idle=34.0s
2024-09-24T17:12:05.670247Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=20.3s time.idle=33.6s
2024-09-24T17:12:05.673989Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: close time.busy=21.5s time.idle=32.2s
2024-09-24T17:12:05.674004Z  INFO breakdown_reveal_aggregation{total=1474}:aggregate_values{num_rows=118}: ipa_core::protocol::ipa_prf::aggregation: new

akoshelev commented 20 hours ago

it is still happening: https://github.com/private-attribution/ipa/actions/runs/11136370331/job/30948030558?pr=1327 even after #1325

andyleiserson commented 6 hours ago

The current failure symptom is slightly different than the original. I'm also not clear on the relation between this issue and the stack overflow issue.

Is it possible that the iteration reduction in #1314 was not necessary, and if that's the case, do we want to revert it?

If some of the stack overflows are manifesting as hangs, should that be tracked as a separate issue from the overflows themselves?

akoshelev commented 6 hours ago

If some of the stack overflows are manifesting as hangs, should that be tracked as a separate issue from the overflows themselves?

Yea we probably want @cberkhoff here as he was investigating that issue. I don't think I have good understanding whether these hangs were caused by stack overflows or not.

akoshelev commented 5 hours ago

Is it possible that the iteration reduction in https://github.com/private-attribution/ipa/pull/1314 was not necessary, and if that's the case, do we want to revert it?

Potentially, I am still suspicious about the time it takes to finish this test

2024-09-24T17:09:50.271047Z  INFO breakdown_reveal_aggregation{total=1474}:apply_dp_padding:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: new
2024-09-24T17:11:11.848035Z  INFO breakdown_reveal_aggregation{total=1474}:shuffle_attribution_outputs: ipa_core::protocol::ipa_prf::shuffle: close time.busy=29.2s time.idle=52.3s
...

2024-09-24T17:11:11.928115Z  INFO breakdown_reveal_aggregation{total=1474}:reveal_breakdowns{total=2622}: ipa_core::protocol::ipa_prf::aggregation::breakdown_reveal: new
2024-09-24T17:12:05.641235Z  INFO breakdown_reveal_aggregation{total=1474}:aggregate_values{num_rows=118}: ipa_core::protocol::ipa_prf::aggregation: new

these are very long waits, so it could be Shuttle running in circles somewhere

cberkhoff commented 5 hours ago

The stack overflows were causing the test to fail, not hang.

akoshelev commented 5 hours ago

hmm, that's weird. Do you have an example of such failure on the CI?

andyleiserson commented 2 hours ago

Some further observations about cargo test -p ipa-core --release --features "shuttle multi-threading" -- protocol::ipa_prf::tests::malicious:

When I run it locally, it fails due to exceeding shuttle's max_steps limit.
The number of shuttle steps in an iteration of the test grows super-linearly with the number of inputs to breakdown_reveal_aggregation.
That step growth is specifically attributable to compute_and_add_tags (Caveat: I determined this by watching the shuttle::current::context_switches() counter. I am not certain this methodology is sound.) I filed #1330, but I didn't work on it right now, because we need to get CI healthy ASAP, and even with an improved compute_and_add_tags, we might still need less padding to make the test fast enough.
Contrary to a theory I offered earlier, changing the active work or batch size does not appear to affect the step count.
I did a run with #1318 reverted, which passed. This does not seem entirely consistent with the previous bullet. Possibly the passing run got lucky?

I am still not sure which of the following is/are true of the failures in CI:

The test hangs.
The test times out but has not hung.
The test is slowing down over time due to memory exhaustion.
There is some problem propagating the max_steps panic to all tasks (either a bug in shuttle or in how we tear down seq/parallel join on error) that allows the test to continue running.

akoshelev commented 36 minutes ago

One thing I noticed when working with Shuttle is that it does not like standard rng. It vends its own random generator which should be used instead: https://docs.rs/shuttle/latest/shuttle/rand/index.html. I think we export that as rng.

If DP padding uses RNG to generate dummies (which I believe it does), it could be worth replacing it with crate::rng. This does not explain why malicious shuffle breaks things though.

private-attribution / ipa

Breakdown reveal aggregation test hangs sometimes #1312