Skip to content

Commit 2a69b41

Browse files
metachrismetachris
authored
log ms into slot when getHeader/getPayload requests start (#508)
* submitBlindedBlock - log milliseconds into slot when request started * also log msIntoSlot in getHeader * log getPayload request start always, for later debugging * cleanup & PR review feedback
1 parent 368f3b0 commit 2a69b41

File tree

6 files changed

+108
-66
lines changed

6 files changed

+108
-66
lines changed

‎Makefile

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,9 @@ lint:
4444
staticcheck ./...
4545
golangci-lint run
4646

47+
.PHONY: lt
48+
lt: lint test
49+
4750
.PHONY: fmt
4851
fmt:
4952
gofmt -s -w .

‎cli/main.go

Lines changed: 10 additions & 56 deletions
Original file line numberDiff line numberDiff line change
@@ -3,13 +3,11 @@ package cli
33
import (
44
"flag"
55
"fmt"
6-
"math/big"
76
"os"
8-
"strconv"
97
"strings"
108
"time"
119

12-
"github.com/flashbots/go-boost-utils/types"
10+
"github.com/flashbots/mev-boost/common"
1311
"github.com/flashbots/mev-boost/config"
1412
"github.com/flashbots/mev-boost/server"
1513
"github.com/sirupsen/logrus"
@@ -25,26 +23,26 @@ const (
2523
var (
2624
// defaults
2725
defaultLogJSON = os.Getenv("LOG_JSON") != ""
28-
defaultLogLevel = getEnv("LOG_LEVEL", "info")
29-
defaultListenAddr = getEnv("BOOST_LISTEN_ADDR", "localhost:18550")
26+
defaultLogLevel = common.GetEnv("LOG_LEVEL", "info")
27+
defaultListenAddr = common.GetEnv("BOOST_LISTEN_ADDR", "localhost:18550")
3028
defaultRelayCheck = os.Getenv("RELAY_STARTUP_CHECK") != ""
31-
defaultRelayMinBidEth = getEnvFloat64("MIN_BID_ETH", 0)
29+
defaultRelayMinBidEth = common.GetEnvFloat64("MIN_BID_ETH", 0)
3230
defaultDisableLogVersion = os.Getenv("DISABLE_LOG_VERSION") == "1" // disables adding the version to every log entry
3331
defaultDebug = os.Getenv("DEBUG") != ""
3432
defaultLogServiceTag = os.Getenv("LOG_SERVICE_TAG")
3533
defaultRelays = os.Getenv("RELAYS")
3634
defaultRelayMonitors = os.Getenv("RELAY_MONITORS")
37-
defaultMaxRetries = getEnvInt("REQUEST_MAX_RETRIES", 5)
35+
defaultMaxRetries = common.GetEnvInt("REQUEST_MAX_RETRIES", 5)
3836

39-
defaultGenesisForkVersion = getEnv("GENESIS_FORK_VERSION", "")
37+
defaultGenesisForkVersion = common.GetEnv("GENESIS_FORK_VERSION", "")
4038
defaultUseSepolia = os.Getenv("SEPOLIA") != ""
4139
defaultUseGoerli = os.Getenv("GOERLI") != ""
4240
defaultUseZhejiang = os.Getenv("ZHEJIANG") != ""
4341

4442
// mev-boost relay request timeouts (see also https://github.com/flashbots/mev-boost/issues/287)
45-
defaultTimeoutMsGetHeader = getEnvInt("RELAY_TIMEOUT_MS_GETHEADER", 950) // timeout for getHeader requests
46-
defaultTimeoutMsGetPayload = getEnvInt("RELAY_TIMEOUT_MS_GETPAYLOAD", 4000) // timeout for getPayload requests
47-
defaultTimeoutMsRegisterValidator = getEnvInt("RELAY_TIMEOUT_MS_REGVAL", 3000) // timeout for registerValidator requests
43+
defaultTimeoutMsGetHeader = common.GetEnvInt("RELAY_TIMEOUT_MS_GETHEADER", 950) // timeout for getHeader requests
44+
defaultTimeoutMsGetPayload = common.GetEnvInt("RELAY_TIMEOUT_MS_GETPAYLOAD", 4000) // timeout for getPayload requests
45+
defaultTimeoutMsRegisterValidator = common.GetEnvInt("RELAY_TIMEOUT_MS_REGVAL", 3000) // timeout for registerValidator requests
4846

4947
relays relayList
5048
relayMonitors relayMonitorList
@@ -194,7 +192,7 @@ func Main() {
194192
log.Infof("minimum bid: %v eth", *relayMinBidEth)
195193
}
196194

197-
relayMinBidWei, err := floatEthTo256Wei(*relayMinBidEth)
195+
relayMinBidWei, err := common.FloatEthTo256Wei(*relayMinBidEth)
198196
if err != nil {
199197
log.WithError(err).Fatal("failed converting min bid")
200198
}
@@ -224,47 +222,3 @@ func Main() {
224222
log.Println("listening on", *listenAddr)
225223
log.Fatal(service.StartHTTPServer())
226224
}
227-
228-
func getEnv(key, defaultValue string) string {
229-
if value, ok := os.LookupEnv(key); ok {
230-
return value
231-
}
232-
return defaultValue
233-
}
234-
235-
func getEnvInt(key string, defaultValue int) int {
236-
if value, ok := os.LookupEnv(key); ok {
237-
val, err := strconv.Atoi(value)
238-
if err == nil {
239-
return val
240-
}
241-
}
242-
return defaultValue
243-
}
244-
245-
func getEnvFloat64(key string, defaultValue float64) float64 {
246-
if value, ok := os.LookupEnv(key); ok {
247-
val, err := strconv.ParseFloat(value, 64)
248-
if err == nil {
249-
return val
250-
}
251-
}
252-
return defaultValue
253-
}
254-
255-
// floatEthTo256Wei converts a float (precision 10) denominated in eth to a U256Str denominated in wei
256-
func floatEthTo256Wei(val float64) (*types.U256Str, error) {
257-
weiU256 := new(types.U256Str)
258-
ethFloat := new(big.Float)
259-
weiFloat := new(big.Float)
260-
weiFloatLessPrecise := new(big.Float)
261-
weiInt := new(big.Int)
262-
263-
ethFloat.SetFloat64(val)
264-
weiFloat.Mul(ethFloat, big.NewFloat(1e18))
265-
weiFloatLessPrecise.SetString(weiFloat.String())
266-
weiFloatLessPrecise.Int(weiInt)
267-
268-
err := weiU256.FromBig(weiInt)
269-
return weiU256, err
270-
}

‎cli/main_test.go

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,25 +5,26 @@ import (
55
"testing"
66

77
"github.com/flashbots/go-boost-utils/types"
8+
"github.com/flashbots/mev-boost/common"
89
"github.com/stretchr/testify/require"
910
)
1011

1112
func TestFloatEthTo256Wei(t *testing.T) {
1213
// test with small input
1314
i := 0.000000000000012345
14-
weiU256, err := floatEthTo256Wei(i)
15+
weiU256, err := common.FloatEthTo256Wei(i)
1516
require.NoError(t, err)
1617
require.Equal(t, types.IntToU256(12345), *weiU256)
1718

1819
// test with zero
1920
i = 0
20-
weiU256, err = floatEthTo256Wei(i)
21+
weiU256, err = common.FloatEthTo256Wei(i)
2122
require.NoError(t, err)
2223
require.Equal(t, types.IntToU256(0), *weiU256)
2324

2425
// test with large input
2526
i = 987654.3
26-
weiU256, err = floatEthTo256Wei(i)
27+
weiU256, err = common.FloatEthTo256Wei(i)
2728
require.NoError(t, err)
2829

2930
r := big.NewInt(9876543)

‎common/common.go

Lines changed: 58 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,58 @@
1+
package common
2+
3+
import (
4+
"math/big"
5+
"os"
6+
"strconv"
7+
8+
"github.com/flashbots/go-boost-utils/types"
9+
)
10+
11+
const (
12+
GenesisTimeMainnet = 1606824023
13+
SlotTimeSecMainnet = 12
14+
)
15+
16+
func GetEnv(key, defaultValue string) string {
17+
if value, ok := os.LookupEnv(key); ok {
18+
return value
19+
}
20+
return defaultValue
21+
}
22+
23+
func GetEnvInt(key string, defaultValue int) int {
24+
if value, ok := os.LookupEnv(key); ok {
25+
val, err := strconv.Atoi(value)
26+
if err == nil {
27+
return val
28+
}
29+
}
30+
return defaultValue
31+
}
32+
33+
func GetEnvFloat64(key string, defaultValue float64) float64 {
34+
if value, ok := os.LookupEnv(key); ok {
35+
val, err := strconv.ParseFloat(value, 64)
36+
if err == nil {
37+
return val
38+
}
39+
}
40+
return defaultValue
41+
}
42+
43+
// FloatEthTo256Wei converts a float (precision 10) denominated in eth to a U256Str denominated in wei
44+
func FloatEthTo256Wei(val float64) (*types.U256Str, error) {
45+
weiU256 := new(types.U256Str)
46+
ethFloat := new(big.Float)
47+
weiFloat := new(big.Float)
48+
weiFloatLessPrecise := new(big.Float)
49+
weiInt := new(big.Int)
50+
51+
ethFloat.SetFloat64(val)
52+
weiFloat.Mul(ethFloat, big.NewFloat(1e18))
53+
weiFloatLessPrecise.SetString(weiFloat.String())
54+
weiFloatLessPrecise.Int(weiInt)
55+
56+
err := weiU256.FromBig(weiInt)
57+
return weiU256, err
58+
}

‎config/vars.go

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@ package config
33
import (
44
"os"
55

6-
"github.com/flashbots/go-utils/cli"
6+
"github.com/flashbots/mev-boost/common"
77
)
88

99
// Set during build
@@ -18,18 +18,23 @@ const (
1818
// Other settings
1919
var (
2020
// ServerReadTimeoutMs sets the maximum duration for reading the entire request, including the body. A zero or negative value means there will be no timeout.
21-
ServerReadTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_READ_TIMEOUT_MS", 1000)
21+
ServerReadTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_READ_TIMEOUT_MS", 1000)
2222

2323
// ServerReadHeaderTimeoutMs sets the amount of time allowed to read request headers.
24-
ServerReadHeaderTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_READ_HEADER_TIMEOUT_MS", 1000)
24+
ServerReadHeaderTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_READ_HEADER_TIMEOUT_MS", 1000)
2525

2626
// ServerWriteTimeoutMs sets the maximum duration before timing out writes of the response.
27-
ServerWriteTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_WRITE_TIMEOUT_MS", 0)
27+
ServerWriteTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_WRITE_TIMEOUT_MS", 0)
2828

2929
// ServerIdleTimeoutMs sets the maximum amount of time to wait for the next request when keep-alives are enabled.
30-
ServerIdleTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_IDLE_TIMEOUT_MS", 0)
30+
ServerIdleTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_IDLE_TIMEOUT_MS", 0)
3131

32-
ServerMaxHeaderBytes = cli.GetEnvInt("MAX_HEADER_BYTES", 4000) // max header byte size for requests for dos prevention
32+
// ServerMaxHeaderBytes defines the max header byte size for requests (for dos prevention)
33+
ServerMaxHeaderBytes = common.GetEnvInt("MAX_HEADER_BYTES", 4000)
3334

35+
// SkipRelaySignatureCheck can be used to disable relay signature check
3436
SkipRelaySignatureCheck = os.Getenv("SKIP_RELAY_SIGNATURE_CHECK") == "1"
37+
38+
GenesisTime = int64(common.GetEnvInt("GENESIS_TIMESTAMP", common.GenesisTimeMainnet))
39+
SlotTimeSec = int64(common.GetEnvInt("SLOT_SEC", common.SlotTimeSecMainnet))
3540
)

‎server/service.go

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -295,6 +295,7 @@ func (m *BoostService) handleGetHeader(w http.ResponseWriter, req *http.Request)
295295
slot := vars["slot"]
296296
parentHashHex := vars["parent_hash"]
297297
pubkey := vars["pubkey"]
298+
298299
log := m.log.WithFields(logrus.Fields{
299300
"method": "getHeader",
300301
"slot": slot,
@@ -319,6 +320,15 @@ func (m *BoostService) handleGetHeader(w http.ResponseWriter, req *http.Request)
319320
return
320321
}
321322

323+
// Log how late into the slot the request starts
324+
slotStartTimestamp := config.GenesisTime + (int64(_slot) * config.SlotTimeSec)
325+
msIntoSlot := time.Now().UTC().UnixMilli() - (slotStartTimestamp * 1000)
326+
log.WithFields(logrus.Fields{
327+
"genesisTime": config.GenesisTime,
328+
"slotTimeSec": config.SlotTimeSec,
329+
"msIntoSlot": msIntoSlot,
330+
}).Infof("getHeader request start - %d milliseconds into slot %d", msIntoSlot, _slot)
331+
322332
result := bidResp{} // the final response, containing the highest bid (if any)
323333
relays := make(map[BlockHashHex][]RelayEntry) // relays that sent the bid for a specific blockHash
324334

@@ -578,12 +588,23 @@ func (m *BoostService) processCapellaPayload(w http.ResponseWriter, req *http.Re
578588
return
579589
}
580590

591+
// Prepare logger
581592
log = log.WithFields(logrus.Fields{
582593
"slot": payload.Message.Slot,
583594
"blockHash": payload.Message.Body.ExecutionPayloadHeader.BlockHash.String(),
584595
"parentHash": payload.Message.Body.ExecutionPayloadHeader.ParentHash.String(),
585596
})
586597

598+
// Log how late into the slot the request starts
599+
slotStartTimestamp := config.GenesisTime + (int64(payload.Message.Slot) * config.SlotTimeSec)
600+
msIntoSlot := time.Now().UTC().UnixMilli() - (slotStartTimestamp * 1000)
601+
log.WithFields(logrus.Fields{
602+
"genesisTime": config.GenesisTime,
603+
"slotTimeSec": config.SlotTimeSec,
604+
"msIntoSlot": msIntoSlot,
605+
}).Infof("submitBlindedBlock request start - %d milliseconds into slot %d", msIntoSlot, payload.Message.Slot)
606+
607+
// Get the bid!
587608
bidKey := bidRespKey{slot: uint64(payload.Message.Slot), blockHash: payload.Message.Body.ExecutionPayloadHeader.BlockHash.String()}
588609
m.bidsLock.Lock()
589610
originalBid := m.bids[bidKey]
@@ -686,7 +707,7 @@ func (m *BoostService) processCapellaPayload(w http.ResponseWriter, req *http.Re
686707

687708
func (m *BoostService) handleGetPayload(w http.ResponseWriter, req *http.Request) {
688709
log := m.log.WithField("method", "getPayload")
689-
log.Debug("getPayload")
710+
log.Debug("getPayload request starts")
690711

691712
// Read the body first, so we can log it later on error
692713
body, err := io.ReadAll(req.Body)

0 commit comments

Comments
 (0)