rpc: improve startup, error, and tx submission logging

eth/rpc/endpoints.go

@@ -18,6 +18,7 @@ package rpc
 
 import (
 	"net"
+	"strings"
 
 	"github.com/ethereum/go-ethereum/log"
 )
@@ -31,20 +32,25 @@ func StartHTTPEndpoint(endpoint string, apis []API, modules []string, rmf *RpcMe
 	}
 	// Register all the APIs exposed by the services
 	handler := NewServer()
+	registered := make(map[string]struct{})
 	for _, api := range apis {
 		if whitelist[api.Namespace] || (len(whitelist) == 0 && api.Public) {
 			if err := handler.RegisterName(api.Namespace, api.Service, rmf); err != nil {
+				log.Info("HTTP registration failed", "namespace", api.Namespace, "error", err)
 				return nil, nil, err
 			}
+			registered[api.Namespace] = struct{}{}
 			log.Debug("HTTP registered", "namespace", api.Namespace)
 		}
 	}
+	logUnavailableModules("HTTP", modules, registered)
 	// All APIs registered, start the HTTP listener
 	var (
 		listener net.Listener
 		err      error
 	)
 	if listener, err = net.Listen("tcp", endpoint); err != nil {
+		log.Warn("HTTP listener open failed", "endpoint", endpoint, "error", err)
 		return nil, nil, err
 	}
 	go NewHTTPServer(cors, vhosts, timeouts, handler).Serve(listener)
@@ -61,20 +67,25 @@ func StartWSEndpoint(endpoint string, apis []API, modules []string, rmf *RpcMeth
 	}
 	// Register all the APIs exposed by the services
 	handler := NewServer()
+	registered := make(map[string]struct{})
 	for _, api := range apis {
 		if exposeAll || whitelist[api.Namespace] || (len(whitelist) == 0 && api.Public) {
 			if err := handler.RegisterName(api.Namespace, api.Service, rmf); err != nil {
+				log.Info("WebSocket registration failed", "namespace", api.Namespace, "error", err)
 				return nil, nil, err
 			}
+			registered[api.Namespace] = struct{}{}
 			log.Debug("WebSocket registered", "service", api.Service, "namespace", api.Namespace)
 		}
 	}
+	logUnavailableModules("WebSocket", modules, registered)
 	// All APIs registered, start the HTTP listener
 	var (
 		listener net.Listener
 		err      error
 	)
 	if listener, err = net.Listen("tcp", endpoint); err != nil {
+		log.Warn("WebSocket listener open failed", "endpoint", endpoint, "error", err)
 		return nil, nil, err
 	}
 	go NewWSServer(wsOrigins, handler).Serve(listener)
@@ -86,17 +97,46 @@ func StartWSEndpoint(endpoint string, apis []API, modules []string, rmf *RpcMeth
 func StartIPCEndpoint(ipcEndpoint string, apis []API, rmf *RpcMethodFilter) (net.Listener, *Server, error) {
 	// Register all the APIs exposed by the services.
 	handler := NewServer()
+	registered := make([]string, 0, len(apis))
+	regMap := make(map[string]struct{})
 	for _, api := range apis {
 		if err := handler.RegisterName(api.Namespace, api.Service, rmf); err != nil {
+			log.Info("IPC registration failed", "namespace", api.Namespace, "error", err)
 			return nil, nil, err
 		}
+		if _, ok := regMap[api.Namespace]; !ok {
+			registered = append(registered, api.Namespace)
+			regMap[api.Namespace] = struct{}{}
+		}
 		log.Debug("IPC registered", "namespace", api.Namespace)
 	}
+	log.Debug("IPCs registered", "namespaces", strings.Join(registered, ","))
 	// All APIs registered, start the IPC listener.
 	listener, err := ipcListen(ipcEndpoint)
 	if err != nil {
+		log.Warn("IPC listener open failed", "endpoint", ipcEndpoint, "error", err)
 		return nil, nil, err
 	}
 	go handler.ServeListener(listener)
 	return listener, handler, nil
 }
+
+func logUnavailableModules(transport string, modules []string, registered map[string]struct{}) {
+	if len(modules) == 0 {
+		return
+	}
+	unavailable := make([]string, 0)
+	for _, module := range modules {
+		if _, ok := registered[module]; !ok {
+			unavailable = append(unavailable, module)
+		}
+	}
+	if len(unavailable) == 0 {
+		return
+	}
+	available := make([]string, 0, len(registered))
+	for module := range registered {
+		available = append(available, module)
+	}
+	log.Warn("Unavailable modules in "+transport+" API list", "unavailable", unavailable, "available", available)
+}

eth/rpc/handler.go

@@ -296,7 +296,11 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess
 	case msg.isCall():
 		resp := h.handleCall(ctx, msg)
 		if resp.Error != nil {
-			h.log.Warn("Served "+msg.Method, "reqid", idForLog{msg.ID}, "t", time.Since(start), "err", resp.Error.Message)
+			logData := []interface{}{"reqid", idForLog{msg.ID}, "t", time.Since(start), "err", resp.Error.Message}
+			if resp.Error.Data != nil {
+				logData = append(logData, "errdata", resp.Error.Data)
+			}
+			h.log.Warn("Served "+msg.Method, logData...)
 		} else {
 			h.log.Debug("Served "+msg.Method, "reqid", idForLog{msg.ID}, "t", time.Since(start))
 		}

rpc/boot/rpc.go

@@ -67,6 +67,7 @@ func StartServers(hmyboot *hmyboot.BootService, apis []rpc.API, config bootnodeC
 		if err := rmf.LoadRpcMethodFiltersFromFile(rpcFilterFilePath); err != nil {
 			return err
 		}
+		utils.Logger().Info().Str("path", rpcFilterFilePath).Msg("Loaded RPC method filter file")
 	} else {
 		rmf.ExposeAll()
 	}
@@ -147,6 +148,7 @@ func startBootServiceHTTP(apis []rpc.API, rmf *rpc.RpcMethodFilter, httpTimeouts
 		Str("url", fmt.Sprintf("http://%s", httpEndpoint)).
 		Str("cors", strings.Join(httpOrigins, ",")).
 		Str("vhosts", strings.Join(httpVirtualHosts, ",")).
+		Strs("modules", HTTPModules).
 		Msg("HTTP endpoint opened")
 
 	fmt.Printf("Started Boot Node RPC server at: %v\n", httpEndpoint)
@@ -160,7 +162,9 @@ func startBootServiceWS(apis []rpc.API, rmf *rpc.RpcMethodFilter) (err error) {
 	}
 
 	utils.Logger().Info().
-		Str("url", fmt.Sprintf("ws://%s", wsEndpoint)).
+		Str("url", fmt.Sprintf("ws://%s", wsListener.Addr())).
+		Str("origins", strings.Join(wsOrigins, ",")).
+		Strs("modules", WSModules).
 		Msg("WebSocket endpoint opened")
 	fmt.Printf("Started Boot Node WS server at: %v\n", wsEndpoint)
 	return nil

rpc/harmony/pool.go

@@ -72,6 +72,14 @@ func (s *PublicPoolService) wait(limiter *rate.Limiter, ctx context.Context) err
 	return nil
 }
 
+func (s *PublicPoolService) txSender(tx *types.Transaction) (common.Address, error) {
+	signer := types.MakeSigner(s.hmy.ChainConfig(), s.hmy.CurrentBlock().Epoch())
+	if tx.IsEthCompatible() {
+		signer = types.NewEIP155Signer(s.hmy.ChainConfig().EthCompatibleChainID)
+	}
+	return types.Sender(signer, tx)
+}
+
 // SendRawTransaction will add the signed transaction to the transaction pool.
 // The sender is responsible for signing the transaction and using the correct nonce.
 func (s *PublicPoolService) SendRawTransaction(
@@ -109,36 +117,47 @@ func (s *PublicPoolService) SendRawTransaction(
 		return common.Hash{}, err
 	}
 
+	from, fromErr := s.txSender(tx)
+
 	// Submit transaction
 	if err := s.hmy.SendTx(ctx, tx); err != nil {
-		utils.Logger().Warn().Err(err).Msg("Could not submit transaction")
+		logger := utils.Logger().Warn().Err(err)
+		if fromErr == nil {
+			logger = logger.Str("from", from.Hex())
+		}
+		if tx.To() != nil {
+			logger = logger.Str("to", tx.To().Hex())
+		}
+		if tx.Value() != nil {
+			logger = logger.Str("value", tx.Value().String())
+		}
+		logger.Msg("Could not submit transaction")
 		return common.Hash{}, err
 	}
 
+	if fromErr != nil {
+		return common.Hash{}, fromErr
+	}
+
 	// Log submission
 	if tx.To() == nil {
-		signer := types.MakeSigner(s.hmy.ChainConfig(), s.hmy.CurrentBlock().Epoch())
-		ethSigner := types.NewEIP155Signer(s.hmy.ChainConfig().EthCompatibleChainID)
-
-		if tx.IsEthCompatible() {
-			signer = ethSigner
-		}
-		from, err := types.Sender(signer, tx)
-		if err != nil {
-			return common.Hash{}, err
-		}
 		addr := crypto.CreateAddress(from, tx.Nonce())
 		utils.Logger().Info().
-			Str("fullhash", tx.Hash().Hex()).
+			Str("hash", tx.Hash().Hex()).
 			Str("hashByType", tx.HashByType().Hex()).
+			Str("from", from.Hex()).
+			Uint64("nonce", tx.Nonce()).
 			Str("contract", common2.MustAddressToBech32(addr)).
+			Str("value", tx.Value().String()).
 			Msg("Submitted contract creation")
 	} else {
 		utils.Logger().Info().
-			Str("fullhash", tx.Hash().Hex()).
+			Str("hash", tx.Hash().Hex()).
 			Str("hashByType", tx.HashByType().Hex()).
+			Str("from", from.Hex()).
+			Uint64("nonce", tx.Nonce()).
 			Str("recipient", tx.To().Hex()).
-			Interface("tx", tx).
+			Str("value", tx.Value().String()).
 			Msg("Submitted transaction")
 	}
 
@@ -187,14 +206,19 @@ func (s *PublicPoolService) SendRawStakingTransaction(
 
 	// Submit transaction
 	if err := s.hmy.SendStakingTx(ctx, tx); err != nil {
-		utils.Logger().Warn().Err(err).Msg("Could not submit staking transaction")
+		utils.Logger().Warn().
+			Err(err).
+			Str("hash", tx.Hash().Hex()).
+			Uint64("nonce", tx.Nonce()).
+			Msg("Could not submit staking transaction")
 		return tx.Hash(), err
 	}
 
 	// Log submission
 	utils.Logger().Info().
-		Str("fullhash", tx.Hash().Hex()).
-		Msg("Submitted Staking transaction")
+		Str("hash", tx.Hash().Hex()).
+		Uint64("nonce", tx.Nonce()).
+		Msg("Submitted staking transaction")
 
 	// Response output is the same for all versions
 	return tx.Hash(), nil

rpc/harmony/rpc.go

@@ -85,9 +85,20 @@ func StartServers(hmy *hmy.Harmony, apis []rpc.API, config nodeconfig.RPCServerC
 		if err := rmf.LoadRpcMethodFiltersFromFile(rpcFilterFilePath); err != nil {
 			return err
 		}
+		utils.Logger().Info().Str("path", rpcFilterFilePath).Msg("Loaded RPC method filter file")
 	} else {
 		rmf.ExposeAll()
 	}
+	utils.Logger().Info().
+		Bool("http", config.HTTPEnabled).
+		Bool("ws", config.WSEnabled).
+		Bool("rateLimiter", config.RateLimiterEnabled).
+		Int("requestsPerSecond", config.RequestsPerSecond).
+		Bool("ethRPCs", config.EthRPCsEnabled).
+		Bool("stakingRPCs", config.StakingRPCsEnabled).
+		Bool("legacyRPCs", config.LegacyRPCsEnabled).
+		Bool("debugRPCs", config.DebugEnabled).
+		Msg("Starting RPC servers")
 	if config.HTTPEnabled {
 		timeouts := rpc.HTTPTimeouts{
 			ReadTimeout:  config.HTTPTimeoutRead,
@@ -154,7 +165,7 @@ func StopServers() error {
 		}
 		wsListener = nil
 		utils.Logger().Info().
-			Str("url", fmt.Sprintf("http://%s", wsEndpoint)).
+			Str("url", fmt.Sprintf("ws://%s", wsEndpoint)).
 			Msg("WS endpoint closed")
 	}
 	if wsHandler != nil {
@@ -256,6 +267,8 @@ func startHTTP(apis []rpc.API, rmf *rpc.RpcMethodFilter, httpTimeouts rpc.HTTPTi
 		Str("url", fmt.Sprintf("http://%s", httpEndpoint)).
 		Str("cors", strings.Join(httpOrigins, ",")).
 		Str("vhosts", strings.Join(httpVirtualHosts, ",")).
+		Strs("modules", HTTPModules).
+		Bool("auth", false).
 		Msg("HTTP endpoint opened")
 	fmt.Printf("Started RPC server at: %v\n", httpEndpoint)
 	return nil
@@ -273,7 +286,9 @@ func startAuthHTTP(apis []rpc.API, rmf *rpc.RpcMethodFilter, httpTimeouts rpc.HT
 		Str("url", fmt.Sprintf("http://%s", httpAuthEndpoint)).
 		Str("cors", strings.Join(httpOrigins, ",")).
 		Str("vhosts", strings.Join(httpVirtualHosts, ",")).
-		Msg("HTTP endpoint opened")
+		Strs("modules", HTTPModules).
+		Bool("auth", true).
+		Msg("HTTP auth endpoint opened")
 	fmt.Printf("Started Auth-RPC server at: %v\n", httpAuthEndpoint)
 	return nil
 }
@@ -286,7 +301,10 @@ func startWS(apis []rpc.API, rmf *rpc.RpcMethodFilter) (err error) {
 
 	utils.Logger().Info().
 		Str("url", fmt.Sprintf("ws://%s", wsListener.Addr())).
-		Msg("WebSocket WS endpoint opened")
+		Str("origins", strings.Join(wsOrigins, ",")).
+		Strs("modules", WSModules).
+		Bool("auth", false).
+		Msg("WebSocket endpoint opened")
 	fmt.Printf("Started WS server at: %v\n", wsEndpoint)
 	return nil
 }
@@ -299,7 +317,10 @@ func startAuthWS(apis []rpc.API, rmf *rpc.RpcMethodFilter) (err error) {
 
 	utils.Logger().Info().
 		Str("url", fmt.Sprintf("ws://%s", wsAuthListener.Addr())).
-		Msg("WebSocket Auth-WS endpoint opened")
+		Str("origins", strings.Join(wsOrigins, ",")).
+		Strs("modules", WSModules).
+		Bool("auth", true).
+		Msg("WebSocket auth endpoint opened")
 	fmt.Printf("Started Auth-WS server at: %v\n", wsAuthEndpoint)
 	return nil
 }