feat(mux): add successful num_registrations to logs

[ManuelBilbao]

For each validator register request, log the number of registered validators and the number of relays where they was successfully registered

Close #218

[ltitanb]

I may be wrong but I would think that @blevkivskyi-everstake is mainly interested in parsing these logs with some side job, in which case having two different logs may be challenging. Currently we don't do any info log in the inner registrer_validation implementation, so what about:

• keeping the log inside there, without returning the value to the outer register_validator
• have some shared struct , to work in both the case where wait for all registrations and not
• I would also log the number of successful registrations (as opposed to the number of successful relays)

[ManuelBilbao]

@ltitanb not sure what you mean in the last item.
My understanding is that the module receives a request and resends it to many relays. So the number of successful responses will be the number of relays that successfully register the request's validators. If you can explain me what you mean by number of successful registrations would be great.

Also, I changed the logs so now they are equal in both cases. If wait_all_registrations is disabled, it will throw another async task to wait all requests and finally log the result. Let me know if that was the expected behaviour

[ank-everstake]

Please see log example here:
#225

num_registrations will mean amount of keys (1000/1000/3000)
num_responses will mean 10/5/3

We would like to see number of validator keys registered in each relay.
Also we want to ask for batching as relays fail to register if number of keys in request is high.

Linked feature-request:
#226

[ManuelBilbao]

Currently we use the mux only for get_header requests, so the register_validator request will send all validators to all relays.
Following your example from #226 , I setup a config with:

1000 keys
5 relays:
    700 allowed keys to use relay-2 and relay-3
    300 allowed keys to use relay-4 and relay-5
    A default relay-1

And sent a register_validator request with all 1000 keys. The logs results were:

stdout:

2025-01-17T15:33:33.318870Z  INFO register_validators{req_id=fb286e5c-3c59-4561-b395-a8bebaddffc2}: all relay registrations finished num_relays=5 num_registrations=1000 total_time=12.471209ms

JSON

{"timestamp":"2025-01-17T15:33:33.318885Z","level":"INFO","fields":{"message":"all relay registrations finished","num_relays":5,"num_registrations":1000,"total_time":"12.471209ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"fb286e5c-3c59-4561-b395-a8bebaddffc2","name":"register_validators"}]}

Let me know if this is ok or you need something different

[ank-everstake]

Could you share DEBUG level logs for this setup to double-check?

[ManuelBilbao]

Sure,
stdout:

2025-01-20T11:07:32.892778Z  INFO register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}: ua="bruno-runtime/1.37.0" num_registrations=1000
2025-01-20T11:07:32.908301Z DEBUG register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}:handler{relay_id="relay-1" retry=0}: registration successful code=200 latency=14.306375ms
2025-01-20T11:07:32.908584Z  INFO register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}: register validator successful
2025-01-20T11:07:32.909025Z DEBUG register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}:handler{relay_id="relay-5" retry=0}: registration successful code=200 latency=14.95625ms
2025-01-20T11:07:32.909193Z DEBUG register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}:handler{relay_id="relay-3" retry=0}: registration successful code=200 latency=15.188834ms
2025-01-20T11:07:32.909767Z DEBUG register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}:handler{relay_id="relay-2" retry=0}: registration successful code=200 latency=15.690709ms
2025-01-20T11:07:32.910288Z DEBUG register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}:handler{relay_id="relay-4" retry=0}: registration successful code=200 latency=16.177416ms
2025-01-20T11:07:32.910377Z  INFO register_validators{req_id=a0bfa554-2ddc-4816-9cb3-9366bc166bc2}: all relay registrations finished num_relays=5 num_registrations=1000 total_time=16.712375ms

JSON:

{"timestamp":"2025-01-20T11:07:32.892820Z","level":"INFO","fields":{"ua":"bruno-runtime/1.37.0","num_registrations":1000},"target":"cb_pbs::routes::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"}]}
{"timestamp":"2025-01-20T11:07:32.908335Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"14.306375ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"},{"relay_id":"relay-1","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-20T11:07:32.908595Z","level":"INFO","fields":{"message":"register validator successful"},"target":"cb_pbs::routes::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"}]}
{"timestamp":"2025-01-20T11:07:32.909041Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"14.95625ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"},{"relay_id":"relay-5","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-20T11:07:32.909210Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"15.188834ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"},{"relay_id":"relay-3","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-20T11:07:32.909785Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"15.690709ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"},{"relay_id":"relay-2","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-20T11:07:32.910303Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"16.177416ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"},{"relay_id":"relay-4","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-20T11:07:32.910387Z","level":"INFO","fields":{"message":"all relay registrations finished","num_relays":5,"num_registrations":1000,"total_time":"16.712375ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"a0bfa554-2ddc-4816-9cb3-9366bc166bc2","name":"register_validators"}]}

In this case, the wait_all_registrations config is false, so it returns and logs as soon as the first relay respond successful. But when all the other requests finished, it logs the final results.

Btw, batch size configuration is being addressed in #244.

[ltitanb]

based on the comments above (successful registrations per relay) and the description in the original issue, shouldn't we just add the number of registrations to the registration success log?

commit-boost-client/crates/pbs/src/mev_boost/register_validator.rs

Line 166 in d396f7b

debug!(?code, latency = ?request_latency, "registration successful");