[FEAT] Add more parameter to one log line

[blevkivskyi-everstake]

It would be great to have in one log line more parameters, that could be processed by Grafana/LOKI

Commit-boost:

2025-01-01T04:04:00.405411Z  INFO get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: received header value_eth="0.002629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288

2025-01-01T04:04:00.394390Z DEBUG get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}:handler{relay_id="boost-relay-holesky.flashbots.net"}: received new header latency=262.760568ms value_eth="0.002629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288

2025-01-01T04:04:00.131335Z DEBUG get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: using mux config mux_id="test_mux_2" relays=1 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a

2025-01-01T04:04:00.131283Z  INFO get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: ua="Lighthouse/v6.0.1-0d90135" parent_hash=0x6f1c01d150fed6217b5a4e5c026e5615d957177d4e3e22174c94740ffef3b277 validator_pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a ms_into_slot=131

Mev-boost:

time="2025-**-**T**:**:**.***Z" level=info msg="best bid" blockHash=0x*** blockNumber=*** method=getHeader parentHash=0x*** pubkey=0x*** relays="http://0x***" slot=*** slotUID=***-***-***-***-*** txRoot=0x*** ua=teku/v24.12.1 value=100000000000 version=v1.8.1

This will be useful for Grafana alerting:

[ltitanb]

makes sense, is this specifically for get header or for other calls too?

[blevkivskyi-everstake]

We suggest making all logs for all requests typical and uniform, because it`s will be easier to track and debug this way
As it requires a bit of refactoring we think that it would be also beneficial to choose between raw logs and JSON format

Current

2025-01-09T15:12:00.031744Z  INFO register_validators{req_id=b4a87b1c-bc1a-452a-a55e-95fce7dcaef8}: ua="Lighthouse/v6.0.1-0d90135" num_registrations=24
2025-01-09T15:05:36.423508Z  INFO register_validators{req_id=00c853bf-0faa-4091-b909-c67635d30c4d}: register validator successful
2025-01-09T15:05:36.423402Z DEBUG register_validators{req_id=00c853bf-0faa-4091-b909-c67635d30c4d}:handler{relay_id="bloxroute.holesky.blxrbdn.com" retry=0}: registration successful code=200 latency=391.810984ms
2025-01-09T15:05:36.294046Z DEBUG register_validators{req_id=00c853bf-0faa-4091-b909-c67635d30c4d}:handler{relay_id="boost-relay-holesky.flashbots.net" retry=0}: registration successful code=200 latency=262.483232ms
2025-01-09T15:05:36.100211Z DEBUG register_validators{req_id=00c853bf-0faa-4091-b909-c67635d30c4d}:handler{relay_id="holesky.titanrelay.xyz" retry=0}: registration successful code=200 latency=68.647704ms
2025-01-09T15:05:36.031444Z  INFO register_validators{req_id=00c853bf-0faa-4091-b909-c67635d30c4d}: ua="Lighthouse/v6.0.1-0d90135" num_registrations=24
2025-01-09T14:59:12.469881Z  INFO register_validators{req_id=88570f3f-f0c4-4ef2-98d2-fb688a8dd38a}: register validator successful
2025-01-09T14:59:12.469787Z DEBUG register_validators{req_id=88570f3f-f0c4-4ef2-98d2-fb688a8dd38a}:handler{relay_id="bloxroute.holesky.blxrbdn.com" retry=0}: registration successful code=200 latency=434.058136ms

2025-01-01T04:04:02.884231Z  INFO submit_blinded_block{req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820}: received unblinded block
2025-01-01T04:04:02.884118Z DEBUG submit_blinded_block{req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820}:handler{relay_id="boost-relay-holesky.flashbots.net" retry=0}: received unblinded block latency=2.13104171s block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288
2025-01-01T04:04:02.285163Z  WARN submit_blinded_block{req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820}:handler{relay_id="bloxroute.holesky.blxrbdn.com" retry=1}: failed to get payload (this might be ok if other relays have it) err=relay response error. Code: 500, err: {"code":500,"message":"could not find requested payload"}
2025-01-01T04:04:01.616313Z  WARN submit_blinded_block{req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820}:handler{relay_id="bloxroute.holesky.blxrbdn.com" retry=0}: failed to get payload (this might be ok if other relays have it) err=relay response error. Code: 500, err: {"code":500,"message":"could not find requested payload"}
2025-01-01T04:04:00.751175Z  INFO submit_blinded_block{req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820}: ua="Lighthouse/v6.0.1-0d90135" slot_uuid=627083ef-aa49-40f3-9d31-9d44ccf4f9ce ms_into_slot=751 block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288
2025-01-01T04:04:00.405411Z  INFO get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: received header value_eth="0.002629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288
2025-01-01T04:04:00.394390Z DEBUG get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}:handler{relay_id="boost-relay-holesky.flashbots.net"}: received new header latency=262.760568ms value_eth="0.002629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288
2025-01-01T04:04:00.131335Z DEBUG get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: using mux config mux_id="test_mux_2" relays=1 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
2025-01-01T04:04:00.131283Z  INFO get_header{req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820}: ua="Lighthouse/v6.0.1-0d90135" parent_hash=0x6f1c01d150fed6217b5a4e5c026e5615d957177d4e3e22174c94740ffef3b277 validator_pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a ms_into_slot=131

Proposed raw format

timestamp=2025-01-09T15:05:36.423508Z  log_level=INFO method=register_validators req_id=00c853bf-0faa-4091-b909-c67635d30c4d msg="register validator successful"
timestamp=2025-01-09T15:05:36.423402Z  log_level=INFO method=register_validators req_id=00c853bf-0faa-4091-b909-c67635d30c4d relay_id="bloxroute.holesky.blxrbdn.com" retry=0 msg="registration successful"code=200 latency=391.810984ms num_registrations=7
timestamp=2025-01-09T15:05:36.294046Z  log_level=INFO method=register_validators req_id=00c853bf-0faa-4091-b909-c67635d30c4d relay_id="boost-relay-holesky.flashbots.net" retry=0 msg="registration successful"code=200 latency=262.483232ms num_registrations=7
timestamp=2025-01-09T15:05:36.100211Z  log_level=INFO method=register_validators req_id=00c853bf-0faa-4091-b909-c67635d30c4d relay_id="holesky.titanrelay.xyz" retry=0 msg="registration successful"code=200 latency=68.647704ms num_registrations=7
timestamp=2025-01-09T15:05:36.031444Z  log_level=INFO method=register_validators req_id=00c853bf-0faa-4091-b909-c67635d30c4d ua="Lighthouse/v6.0.1-0d90135" num_registrations=24

timestamp=2025-01-01T04:04:02.884231Z  log_level=INFO method=submit_blinded_block req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820 msg="received unblinded block"
timestamp=2025-01-01T04:04:00.751175Z  log_level=INFO method=submit_blinded_block req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820 relay_id="boost-relay-holesky.flashbots.net" value_eth="0.002629109072852370" ua="Lighthouse/v6.0.1-0d90135" slot_uuid=627083ef-aa49-40f3-9d31-9d44ccf4f9ce ms_into_slot=751ms block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
timestamp=2025-01-01T04:04:02.884118Z  log_level=INFO method=submit_blinded_block req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820 relay_id="bloxroute.holesky.blxrbdn.com" retry=0 msg="received unblinded block" latency=100.13104171ms ms_into_slot=3010.13104171ms value_eth="0.001629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
timestamp=2025-01-01T04:04:02.884118Z  log_level=INFO method=submit_blinded_block req_id=b2d77de7-e5fc-4f53-b5de-94a03ee76bee slot=3316820 relay_id="boost-relay-holesky.flashbots.net" retry=0 msg="received unblinded block" latency=200.13104171ms ms_into_slot=3003.13104171ms value_eth="0.002529109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
timestamp=2025-01-01T04:04:00.394390Z  log_level=INFO method=get_header req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820 relay_id="boost-relay-holesky.flashbots.net" msg="received new header" latency=262.760568ms value_eth="0.002629109072852370" block_hash=0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
timestamp=2025-01-01T04:04:00.131335Z  log_level=INFO method=get_header req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820 msg="using mux config mux_id='test_mux_2'" relays=1 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a
timestamp=2025-01-01T04:04:00.131283Z  log_level=INFO method=get_header req_id=2869e01c-a39d-4793-805c-29067db47846 slot=3316820 ua="Lighthouse/v6.0.1-0d90135" parent_hash=0x6f1c01d150fed6217b5a4e5c026e5615d957177d4e3e22174c94740ffef3b277 pubkey=0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a ms_into_slot=131ms

Proposed json format

{"timestamp":"2025-01-09T15:05:36.423508Z","log_level":"INFO","method":"register_validators","req_id":"00c853bf-0faa-4091-b909-c67635d30c4d","msg":"register validator successful"}
{"timestamp":"2025-01-09T15:05:36.423402Z","log_level":"INFO","method":"register_validators","req_id":"00c853bf-0faa-4091-b909-c67635d30c4d","relay_id":"bloxroute.holesky.blxrbdn.com","retry":0,"msg":"registration successful","code":200,"latency":"391.810984ms","num_registrations":7}
{"timestamp":"2025-01-09T15:05:36.294046Z","log_level":"INFO","method":"register_validators","req_id":"00c853bf-0faa-4091-b909-c67635d30c4d","relay_id":"boost-relay-holesky.flashbots.net","retry":0,"msg":"registration successful","code":200,"latency":"262.483232ms","num_registrations":7}
{"timestamp":"2025-01-09T15:05:36.100211Z","log_level":"INFO","method":"register_validators","req_id":"00c853bf-0faa-4091-b909-c67635d30c4d","relay_id":"holesky.titanrelay.xyz","retry":0,"msg":"registration successful","code":200,"latency":"68.647704ms","num_registrations":7}
{"timestamp":"2025-01-09T15:05:36.031444Z","log_level":"INFO","method":"register_validators","req_id":"00c853bf-0faa-4091-b909-c67635d30c4d","ua":"Lighthouse/v6.0.1-0d90135","num_registrations":24}

{"timestamp":"2025-01-01T04:04:02.884231Z","log_level":"INFO","method":"submit_blinded_block","req_id":"b2d77de7-e5fc-4f53-b5de-94a03ee76bee","slot":3316820,"msg":"received unblinded block"}
{"timestamp":"2025-01-01T04:04:00.751175Z","log_level":"INFO","method":"submit_blinded_block","req_id":"b2d77de7-e5fc-4f53-b5de-94a03ee76bee","slot":3316820,"relay_id":"boost-relay-holesky.flashbots.net","value_eth":"0.002629109072852370","ua":"Lighthouse/v6.0.1-0d90135","slot_uuid":"627083ef-aa49-40f3-9d31-9d44ccf4f9ce","ms_into_slot":"751ms","block_hash":"0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288","pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a"}
{"timestamp":"2025-01-01T04:04:02.884118Z","log_level":"INFO","method":"submit_blinded_block","req_id":"b2d77de7-e5fc-4f53-b5de-94a03ee76bee","slot":3316820,"relay_id":"bloxroute.holesky.blxrbdn.com","retry":0,"msg":"received unblinded block","latency":"100.13104171ms","ms_into_slot":"3010.13104171ms","value_eth":"0.001629109072852370","block_hash":"0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288","pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a"}
{"timestamp":"2025-01-01T04:04:02.884118Z","log_level":"INFO","method":"submit_blinded_block","req_id":"b2d77de7-e5fc-4f53-b5de-94a03ee76bee","slot":3316820,"relay_id":"boost-relay-holesky.flashbots.net","retry":0,"msg":"received unblinded block","latency":"200.13104171ms","ms_into_slot":"3003.13104171ms","value_eth":"0.002529109072852370","block_hash":"0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288","pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a"}
{"timestamp":"2025-01-01T04:04:00.394390Z","log_level":"INFO","method":"get_header","req_id":"2869e01c-a39d-4793-805c-29067db47846","slot":3316820,"relay_id":"boost-relay-holesky.flashbots.net","msg":"received new header","latency":"262.760568ms","value_eth":"0.002629109072852370","block_hash":"0x8a4873e7d485d56fc28bd4d15ed21f259b243b6449a4fab71561693fe208d288","pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a"}
{"timestamp":"2025-01-01T04:04:00.131335Z","log_level":"INFO","method":"get_header","req_id":"2869e01c-a39d-4793-805c-29067db47846","slot":3316820,"msg":"using mux config mux_id='test_mux_2'","relays":1,"pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a"}
{"timestamp":"2025-01-01T04:04:00.131283Z","log_level":"INFO","method":"get_header","req_id":"2869e01c-a39d-4793-805c-29067db47846","slot":3316820,"ua":"Lighthouse/v6.0.1-0d90135","parent_hash":"0x6f1c01d150fed6217b5a4e5c026e5615d957177d4e3e22174c94740ffef3b277","pubkey":"0xb28dbbcec926781dcc028c0601ffbb0df6316ba41fac800ffd650e9b8b00414fc34a0c77ba78299883aab9254ca1554a","ms_into_slot":"131ms"}

[ltitanb]

To clarify, currently JSON logs are logged to file, while those you shared are logged to stdout.

Example of current JSON logs:

{"timestamp":"2025-01-08T23:57:02.364810Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"140.046259ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"8fe0f1f1-2060-4353-9407-3dfe5f835daa","name":"register_validators"},{"relay_id":"aestus-holesky","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-08T23:57:02.466376Z","level":"DEBUG","fields":{"message":"registration successful","code":"200","latency":"241.610066ms"},"target":"cb_pbs::mev_boost::register_validator","spans":[{"req_id":"8fe0f1f1-2060-4353-9407-3dfe5f835daa","name":"register_validators"},{"relay_id":"flashbots-holesky","retry":0,"name":"handler"}]}
{"timestamp":"2025-01-08T23:57:02.466458Z","level":"INFO","fields":{"message":"register validator successful"},"target":"cb_pbs::routes::register_validator","spans":[{"req_id":"8fe0f1f1-2060-4353-9407-3dfe5f835daa","name":"register_validators"}]}
{"timestamp":"2025-01-08T23:57:02.487090Z","level":"INFO","fields":{"ua":"Lighthouse/v5.3.0-2e0eb6d","num_registrations":500},"target":"cb_pbs::routes::register_validator","spans":[{"req_id":"f2d65af0-69e4-48d0-88e4-b0badd3564a6","name":"register_validators"}]}

is that helpful or you would want the fields all flattened out?

[blevkivskyi-everstake]

Can you add an option to change the log format, as well as the ability to change the log output file/stdout for all log levels? Additionally, please update the documentation to reflect the changes made to the log format.

Please pay attention that we added some changes into log

[ltitanb]

fixed in #281