log ms into slot when getHeader/getPayload requests start (flashbots#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

Makefile

@@ -44,6 +44,9 @@ lint:
 	staticcheck ./...
 	golangci-lint run
 
+.PHONY: lt
+lt: lint test
+
 .PHONY: fmt
 fmt:
 	gofmt -s -w .

cli/main.go

@@ -3,13 +3,11 @@ package cli
 import (
 	"flag"
 	"fmt"
-	"math/big"
 	"os"
-	"strconv"
 	"strings"
 	"time"
 
-	"github.com/flashbots/go-boost-utils/types"
+	"github.com/flashbots/mev-boost/common"
 	"github.com/flashbots/mev-boost/config"
 	"github.com/flashbots/mev-boost/server"
 	"github.com/sirupsen/logrus"
@@ -25,26 +23,26 @@ const (
 var (
 	// defaults
 	defaultLogJSON           = os.Getenv("LOG_JSON") != ""
-	defaultLogLevel          = getEnv("LOG_LEVEL", "info")
-	defaultListenAddr        = getEnv("BOOST_LISTEN_ADDR", "localhost:18550")
+	defaultLogLevel          = common.GetEnv("LOG_LEVEL", "info")
+	defaultListenAddr        = common.GetEnv("BOOST_LISTEN_ADDR", "localhost:18550")
 	defaultRelayCheck        = os.Getenv("RELAY_STARTUP_CHECK") != ""
-	defaultRelayMinBidEth    = getEnvFloat64("MIN_BID_ETH", 0)
+	defaultRelayMinBidEth    = common.GetEnvFloat64("MIN_BID_ETH", 0)
 	defaultDisableLogVersion = os.Getenv("DISABLE_LOG_VERSION") == "1" // disables adding the version to every log entry
 	defaultDebug             = os.Getenv("DEBUG") != ""
 	defaultLogServiceTag     = os.Getenv("LOG_SERVICE_TAG")
 	defaultRelays            = os.Getenv("RELAYS")
 	defaultRelayMonitors     = os.Getenv("RELAY_MONITORS")
-	defaultMaxRetries        = getEnvInt("REQUEST_MAX_RETRIES", 5)
+	defaultMaxRetries        = common.GetEnvInt("REQUEST_MAX_RETRIES", 5)
 
-	defaultGenesisForkVersion = getEnv("GENESIS_FORK_VERSION", "")
+	defaultGenesisForkVersion = common.GetEnv("GENESIS_FORK_VERSION", "")
 	defaultUseSepolia         = os.Getenv("SEPOLIA") != ""
 	defaultUseGoerli          = os.Getenv("GOERLI") != ""
 	defaultUseZhejiang        = os.Getenv("ZHEJIANG") != ""
 
 	// mev-boost relay request timeouts (see also https://github.com/flashbots/mev-boost/issues/287)
-	defaultTimeoutMsGetHeader         = getEnvInt("RELAY_TIMEOUT_MS_GETHEADER", 950)   // timeout for getHeader requests
-	defaultTimeoutMsGetPayload        = getEnvInt("RELAY_TIMEOUT_MS_GETPAYLOAD", 4000) // timeout for getPayload requests
-	defaultTimeoutMsRegisterValidator = getEnvInt("RELAY_TIMEOUT_MS_REGVAL", 3000)     // timeout for registerValidator requests
+	defaultTimeoutMsGetHeader         = common.GetEnvInt("RELAY_TIMEOUT_MS_GETHEADER", 950)   // timeout for getHeader requests
+	defaultTimeoutMsGetPayload        = common.GetEnvInt("RELAY_TIMEOUT_MS_GETPAYLOAD", 4000) // timeout for getPayload requests
+	defaultTimeoutMsRegisterValidator = common.GetEnvInt("RELAY_TIMEOUT_MS_REGVAL", 3000)     // timeout for registerValidator requests
 
 	relays        relayList
 	relayMonitors relayMonitorList
@@ -194,7 +192,7 @@ func Main() {
 		log.Infof("minimum bid: %v eth", *relayMinBidEth)
 	}
 
-	relayMinBidWei, err := floatEthTo256Wei(*relayMinBidEth)
+	relayMinBidWei, err := common.FloatEthTo256Wei(*relayMinBidEth)
 	if err != nil {
 		log.WithError(err).Fatal("failed converting min bid")
 	}
@@ -224,47 +222,3 @@ func Main() {
 	log.Println("listening on", *listenAddr)
 	log.Fatal(service.StartHTTPServer())
 }
-
-func getEnv(key, defaultValue string) string {
-	if value, ok := os.LookupEnv(key); ok {
-		return value
-	}
-	return defaultValue
-}
-
-func getEnvInt(key string, defaultValue int) int {
-	if value, ok := os.LookupEnv(key); ok {
-		val, err := strconv.Atoi(value)
-		if err == nil {
-			return val
-		}
-	}
-	return defaultValue
-}
-
-func getEnvFloat64(key string, defaultValue float64) float64 {
-	if value, ok := os.LookupEnv(key); ok {
-		val, err := strconv.ParseFloat(value, 64)
-		if err == nil {
-			return val
-		}
-	}
-	return defaultValue
-}
-
-// floatEthTo256Wei converts a float (precision 10) denominated in eth to a U256Str denominated in wei
-func floatEthTo256Wei(val float64) (*types.U256Str, error) {
-	weiU256 := new(types.U256Str)
-	ethFloat := new(big.Float)
-	weiFloat := new(big.Float)
-	weiFloatLessPrecise := new(big.Float)
-	weiInt := new(big.Int)
-
-	ethFloat.SetFloat64(val)
-	weiFloat.Mul(ethFloat, big.NewFloat(1e18))
-	weiFloatLessPrecise.SetString(weiFloat.String())
-	weiFloatLessPrecise.Int(weiInt)
-
-	err := weiU256.FromBig(weiInt)
-	return weiU256, err
-}

cli/main_test.go

@@ -5,25 +5,26 @@ import (
 	"testing"
 
 	"github.com/flashbots/go-boost-utils/types"
+	"github.com/flashbots/mev-boost/common"
 	"github.com/stretchr/testify/require"
 )
 
 func TestFloatEthTo256Wei(t *testing.T) {
 	// test with small input
 	i := 0.000000000000012345
-	weiU256, err := floatEthTo256Wei(i)
+	weiU256, err := common.FloatEthTo256Wei(i)
 	require.NoError(t, err)
 	require.Equal(t, types.IntToU256(12345), *weiU256)
 
 	// test with zero
 	i = 0
-	weiU256, err = floatEthTo256Wei(i)
+	weiU256, err = common.FloatEthTo256Wei(i)
 	require.NoError(t, err)
 	require.Equal(t, types.IntToU256(0), *weiU256)
 
 	// test with large input
 	i = 987654.3
-	weiU256, err = floatEthTo256Wei(i)
+	weiU256, err = common.FloatEthTo256Wei(i)
 	require.NoError(t, err)
 
 	r := big.NewInt(9876543)

common/common.go

@@ -0,0 +1,58 @@
+package common
+
+import (
+	"math/big"
+	"os"
+	"strconv"
+
+	"github.com/flashbots/go-boost-utils/types"
+)
+
+const (
+	GenesisTimeMainnet = 1606824023
+	SlotTimeSecMainnet = 12
+)
+
+func GetEnv(key, defaultValue string) string {
+	if value, ok := os.LookupEnv(key); ok {
+		return value
+	}
+	return defaultValue
+}
+
+func GetEnvInt(key string, defaultValue int) int {
+	if value, ok := os.LookupEnv(key); ok {
+		val, err := strconv.Atoi(value)
+		if err == nil {
+			return val
+		}
+	}
+	return defaultValue
+}
+
+func GetEnvFloat64(key string, defaultValue float64) float64 {
+	if value, ok := os.LookupEnv(key); ok {
+		val, err := strconv.ParseFloat(value, 64)
+		if err == nil {
+			return val
+		}
+	}
+	return defaultValue
+}
+
+// FloatEthTo256Wei converts a float (precision 10) denominated in eth to a U256Str denominated in wei
+func FloatEthTo256Wei(val float64) (*types.U256Str, error) {
+	weiU256 := new(types.U256Str)
+	ethFloat := new(big.Float)
+	weiFloat := new(big.Float)
+	weiFloatLessPrecise := new(big.Float)
+	weiInt := new(big.Int)
+
+	ethFloat.SetFloat64(val)
+	weiFloat.Mul(ethFloat, big.NewFloat(1e18))
+	weiFloatLessPrecise.SetString(weiFloat.String())
+	weiFloatLessPrecise.Int(weiInt)
+
+	err := weiU256.FromBig(weiInt)
+	return weiU256, err
+}

config/vars.go

@@ -3,7 +3,7 @@ package config
 import (
 	"os"
 
-	"github.com/flashbots/go-utils/cli"
+	"github.com/flashbots/mev-boost/common"
 )
 
 // Set during build
@@ -18,18 +18,23 @@ const (
 // Other settings
 var (
 	// ServerReadTimeoutMs sets the maximum duration for reading the entire request, including the body. A zero or negative value means there will be no timeout.
-	ServerReadTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_READ_TIMEOUT_MS", 1000)
+	ServerReadTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_READ_TIMEOUT_MS", 1000)
 
 	// ServerReadHeaderTimeoutMs sets the amount of time allowed to read request headers.
-	ServerReadHeaderTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_READ_HEADER_TIMEOUT_MS", 1000)
+	ServerReadHeaderTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_READ_HEADER_TIMEOUT_MS", 1000)
 
 	// ServerWriteTimeoutMs sets the maximum duration before timing out writes of the response.
-	ServerWriteTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_WRITE_TIMEOUT_MS", 0)
+	ServerWriteTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_WRITE_TIMEOUT_MS", 0)
 
 	// ServerIdleTimeoutMs sets the maximum amount of time to wait for the next request when keep-alives are enabled.
-	ServerIdleTimeoutMs = cli.GetEnvInt("MEV_BOOST_SERVER_IDLE_TIMEOUT_MS", 0)
+	ServerIdleTimeoutMs = common.GetEnvInt("MEV_BOOST_SERVER_IDLE_TIMEOUT_MS", 0)
 
-	ServerMaxHeaderBytes = cli.GetEnvInt("MAX_HEADER_BYTES", 4000) // max header byte size for requests for dos prevention
+	// ServerMaxHeaderBytes defines the max header byte size for requests (for dos prevention)
+	ServerMaxHeaderBytes = common.GetEnvInt("MAX_HEADER_BYTES", 4000)
 
+	// SkipRelaySignatureCheck can be used to disable relay signature check
 	SkipRelaySignatureCheck = os.Getenv("SKIP_RELAY_SIGNATURE_CHECK") == "1"
+
+	GenesisTime = int64(common.GetEnvInt("GENESIS_TIMESTAMP", common.GenesisTimeMainnet))
+	SlotTimeSec = int64(common.GetEnvInt("SLOT_SEC", common.SlotTimeSecMainnet))
 )

server/service.go

@@ -295,6 +295,7 @@ func (m *BoostService) handleGetHeader(w http.ResponseWriter, req *http.Request)
 	slot := vars["slot"]
 	parentHashHex := vars["parent_hash"]
 	pubkey := vars["pubkey"]
+
 	log := m.log.WithFields(logrus.Fields{
 		"method":     "getHeader",
 		"slot":       slot,
@@ -319,6 +320,15 @@ func (m *BoostService) handleGetHeader(w http.ResponseWriter, req *http.Request)
 		return
 	}
 
+	// Log how late into the slot the request starts
+	slotStartTimestamp := config.GenesisTime + (int64(_slot) * config.SlotTimeSec)
+	msIntoSlot := time.Now().UTC().UnixMilli() - (slotStartTimestamp * 1000)
+	log.WithFields(logrus.Fields{
+		"genesisTime": config.GenesisTime,
+		"slotTimeSec": config.SlotTimeSec,
+		"msIntoSlot":  msIntoSlot,
+	}).Infof("getHeader request start - %d milliseconds into slot %d", msIntoSlot, _slot)
+
 	result := bidResp{}                           // the final response, containing the highest bid (if any)
 	relays := make(map[BlockHashHex][]RelayEntry) // relays that sent the bid for a specific blockHash
 
@@ -578,12 +588,23 @@ func (m *BoostService) processCapellaPayload(w http.ResponseWriter, req *http.Re
 		return
 	}
 
+	// Prepare logger
 	log = log.WithFields(logrus.Fields{
 		"slot":       payload.Message.Slot,
 		"blockHash":  payload.Message.Body.ExecutionPayloadHeader.BlockHash.String(),
 		"parentHash": payload.Message.Body.ExecutionPayloadHeader.ParentHash.String(),
 	})
 
+	// Log how late into the slot the request starts
+	slotStartTimestamp := config.GenesisTime + (int64(payload.Message.Slot) * config.SlotTimeSec)
+	msIntoSlot := time.Now().UTC().UnixMilli() - (slotStartTimestamp * 1000)
+	log.WithFields(logrus.Fields{
+		"genesisTime": config.GenesisTime,
+		"slotTimeSec": config.SlotTimeSec,
+		"msIntoSlot":  msIntoSlot,
+	}).Infof("submitBlindedBlock request start - %d milliseconds into slot %d", msIntoSlot, payload.Message.Slot)
+
+	// Get the bid!
 	bidKey := bidRespKey{slot: uint64(payload.Message.Slot), blockHash: payload.Message.Body.ExecutionPayloadHeader.BlockHash.String()}
 	m.bidsLock.Lock()
 	originalBid := m.bids[bidKey]
@@ -686,7 +707,7 @@ func (m *BoostService) processCapellaPayload(w http.ResponseWriter, req *http.Re
 
 func (m *BoostService) handleGetPayload(w http.ResponseWriter, req *http.Request) {
 	log := m.log.WithField("method", "getPayload")
-	log.Debug("getPayload")
+	log.Debug("getPayload request starts")
 
 	// Read the body first, so we can log it later on error
 	body, err := io.ReadAll(req.Body)