log ms into slot when getHeader/getPayload requests start

[metachris]

📝 Summary

Log how late into the slot the getHeader and getPayload requests start.

This is particularly useful if proposers submit logs to debug the "too late request" response from the relay (i.e. when the relay received the request >4 sec into the slot). To be specific, this can tell whether the request started too late in the first place, or if it's the network between the proposer and relay

Moved the GetEnv* methods to a new common package, which also holds the default (mainnet) genesis time and slot time (12 sec). This removes the import of go-utils/cli across the package too!

---

✅ I have run these commands

• make lint
• make test-race
• go mod tidy

[codecov-commenter]

Codecov Report

Merging #508 (41aafa4) into develop (54eeaa2) will decrease coverage by 0.74%.
The diff coverage is 64.84%.

❗ Your organization is not using the GitHub App Integration. As a result you may experience degraded service beginning May 15th. Please install the Github App Integration for your organization. Read more.

@@             Coverage Diff             @@
##           develop     #508      +/-   ##
===========================================
- Coverage    70.24%   69.50%   -0.74%     
===========================================
  Files            6        8       +2     
  Lines          541     1256     +715     
===========================================
+ Hits           380      873     +493     
- Misses         132      336     +204     
- Partials        29       47      +18     

Flag	Coverage Δ
unittests	69.50% <64.84%> (-0.74%)	⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
cli/main.go	0.00% <0.00%> (ø)
cli/types.go	0.00% <0.00%> (ø)
server/mock_types.go	100.00% <ø> (ø)
server/types.go	70.00% <70.00%> (ø)
server/service.go	76.57% <74.14%> (+4.56%)	⬆️
server/utils.go	82.23% <84.80%> (+14.66%)	⬆️
server/mock_relay.go	88.44% <90.81%> (+5.58%)	⬆️
server/relay_entry.go	90.00% <100.00%> (+8.75%)	⬆️

... and 1 file with indirect coverage changes

[metachris]

Added one more commit to log with Info level when the getPayload request starts. This will be useful when debugging bug reports like #519

[michaelneuder]

tiny comments, but LGTM

[michaelneuder]

tiny comments, but LGTM

[ralexstokes]

makes sense and this PR in isolation generally makes sense

do we also want to log timings on the "backend" of each request, rather than just the "frontend" like we do in this PR?

[metachris]

do we also want to log timings on the "backend" of each request, rather than just the "frontend" like we do in this PR?

what do you mean with that?

[ralexstokes]

right now it just timestamps when the request starts, we could also log the time when the request finishes (the "backend")

e.g. add a log on 705 about finishing to match the log on 605 about starting

[metachris]

when the request finishes (the "backend")

this is not what's typically referred to as "the backend".

I don't think we need another log there, we already have a log when the payload was received from the relay, and at the end of the function, the HTTP middleware also logs the complete request summary

[michaelneuder]

lgtm!