Minor improvements in logging

Author: swift1337

cmd/tss/tss_http.go

@@ -129,36 +129,36 @@ func (t *HTTPServer) keySignHandler(w http.ResponseWriter, r *http.Request) {
 		w.WriteHeader(http.StatusMethodNotAllowed)
 		return
 	}
+
 	defer func() {
 		if err := r.Body.Close(); nil != err {
 			t.logger.Error().Err(err).Msg("fail to close request body")
 		}
 	}()
-	t.logger.Info().Msg("receive key sign request")
 
 	var keySignReq keysign.Request
-	decoder := json.NewDecoder(r.Body)
-	if err := decoder.Decode(&keySignReq); nil != err {
+
+	if err := json.NewDecoder(r.Body).Decode(&keySignReq); nil != err {
 		t.logger.Error().Err(err).Msg("fail to decode key sign request")
 		w.WriteHeader(http.StatusBadRequest)
 		return
 	}
-	t.logger.Info().Any("request", keySignReq).Msg("received key sign request")
+
 	signResp, err := t.tssServer.KeySign(keySignReq)
 	if err != nil {
 		t.logger.Error().Err(err).Msg("fail to key sign")
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
-	jsonResult, err := json.MarshalIndent(signResp, "", "	")
+	jsonResult, err := json.MarshalIndent(signResp, "", "  ")
 	if err != nil {
 		t.logger.Error().Err(err).Msg("fail to marshal response to json message")
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
-	_, err = w.Write(jsonResult)
-	if err != nil {
+
+	if _, err = w.Write(jsonResult); err != nil {
 		t.logger.Error().Err(err).Msg("fail to write response")
 	}
 }

keysign/ecdsa/tss_keysign.go

@@ -107,6 +107,7 @@ func (tKeySign *TssKeySign) SignMessage(
 		tKeySign.logger.Info().Msg("we are not in this rounds key sign")
 		return nil, nil
 	}
+
 	threshold, err := conversion.GetThreshold(len(localStateItem.ParticipantKeys))
 	if err != nil {
 		return nil, errors.New("fail to get threshold")
@@ -147,11 +148,15 @@ func (tKeySign *TssKeySign) SignMessage(
 
 	blameMgr := tKeySign.tssCommonStruct.GetBlameMgr()
 	partyIDMap := conversion.SetupPartyIDMap(partiesID)
-	err1 := conversion.SetupIDMaps(partyIDMap, tKeySign.tssCommonStruct.PartyIDtoP2PID)
-	err2 := conversion.SetupIDMaps(partyIDMap, blameMgr.PartyIDtoP2PID)
-	if err1 != nil || err2 != nil {
-		tKeySign.logger.Error().Err(err).Msg("error in creating mapping between partyID and P2P ID")
-		return nil, err
+
+	err = conversion.SetupIDMaps(partyIDMap, tKeySign.tssCommonStruct.PartyIDtoP2PID)
+	if err != nil {
+		return nil, fmt.Errorf("fail to setup id maps #1: %w", err)
+	}
+
+	err = conversion.SetupIDMaps(partyIDMap, blameMgr.PartyIDtoP2PID)
+	if err != nil {
+		return nil, fmt.Errorf("fail to setup id maps #2: %w", err)
 	}
 
 	tKeySign.tssCommonStruct.SetPartyInfo(&common.PartyInfo{
@@ -198,7 +203,7 @@ func (tKeySign *TssKeySign) SignMessage(
 		a := new(big.Int).SetBytes(results[i].M)
 		b := new(big.Int).SetBytes(results[j].M)
 
-		return a.Cmp(b) != -1
+		return a.Cmp(b) >= 0
 	})
 
 	return results, nil

keysign/eddsa/tss_keysign.go

@@ -205,7 +205,7 @@ func (tKeySign *KeySign) SignMessage(
 		a := new(big.Int).SetBytes(results[i].M)
 		b := new(big.Int).SetBytes(results[j].M)
 
-		return a.Cmp(b) != -1
+		return a.Cmp(b) >= 0
 	})
 
 	return results, nil

keysign/request.go

@@ -1,5 +1,7 @@
 package keysign
 
+import "github.com/rs/zerolog"
+
 // Request request to sign a message
 type Request struct {
 	PoolPubKey    string   `json:"pool_pub_key"` // pub key of the pool that we would like to send this message from
@@ -18,3 +20,8 @@ func NewRequest(pk string, msgs []string, blockHeight int64, signers []string, v
 		Version:       version,
 	}
 }
+
+func (r *Request) MarshalZerologObject(e *zerolog.Event) {
+	e.Strs("request.messages", r.Messages)
+	e.Int64("request.block_height", r.BlockHeight)
+}

p2p/communication.go

@@ -162,56 +162,63 @@ func (c *Communication) writeToStream(pID peer.ID, msg []byte, msgID string) err
 
 func (c *Communication) readFromStream(stream network.Stream) {
 	peerID := stream.Conn().RemotePeer().String()
-	c.logger.Debug().Msgf("reading from stream of peer: %s", peerID)
+	c.logger.Debug().Str(logs.Peer, peerID).Msg("Reading from peer's stream")
 
 	const timeout = 10 * time.Second
 
-	select {
-	case <-c.stopChan:
+	payload, err := ReadStreamWithBuffer(stream)
+	if err != nil {
+		c.logger.Error().Err(err).Str(logs.Peer, peerID).Msg("fail to read from stream")
+		c.streamMgr.AddStream("UNKNOWN", stream)
+		return
+	}
+
+	var wrappedMsg messages.WrappedMessage
+	if err := json.Unmarshal(payload, &wrappedMsg); nil != err {
+		c.logger.Error().Err(err).Msg("fail to unmarshal wrapped message bytes")
+		c.streamMgr.AddStream("UNKNOWN", stream)
 		return
-	default:
-		dataBuf, err := ReadStreamWithBuffer(stream)
-		if err != nil {
-			c.logger.Error().Err(err).Str(logs.Peer, peerID).Msg("fail to read from stream")
-			c.streamMgr.AddStream("UNKNOWN", stream)
-			return
-		}
-		var wrappedMsg messages.WrappedMessage
-		if err := json.Unmarshal(dataBuf, &wrappedMsg); nil != err {
-			c.logger.Error().Err(err).Msg("fail to unmarshal wrapped message bytes")
-			c.streamMgr.AddStream("UNKNOWN", stream)
-			return
-		}
-		c.logger.Debug().Msgf(">>>>>>>[%s] %s", wrappedMsg.MessageType, string(wrappedMsg.Payload))
-		channel := c.getSubscriber(wrappedMsg.MessageType, wrappedMsg.MsgID)
-		if nil == channel {
-			c.logger.Debug().Msgf("no MsgID %s found for this message", wrappedMsg.MsgID)
-			c.logger.Debug().Msgf("no MsgID %s found for this message", wrappedMsg.MessageType)
-			_ = stream.Reset()
-			return
-		}
-		c.streamMgr.AddStream(wrappedMsg.MsgID, stream)
-		select {
-		case <-time.After(timeout):
-			c.logger.Warn().
-				Str(logs.MsgID, wrappedMsg.MsgID).
-				Str(logs.Peer, peerID).
-				Str("protocol", string(stream.Protocol())).
-				Str("message_type", wrappedMsg.MessageType.String()).
-				Float64("timeout", timeout.Seconds()).
-				Msg("Timeout to send message to channel")
-		case channel <- &Message{
-			PeerID:  stream.Conn().RemotePeer(),
-			Payload: dataBuf}:
-		}
+	}
+
+	channel := c.getSubscriber(wrappedMsg.MessageType, wrappedMsg.MsgID)
+	if nil == channel {
+		c.logger.Debug().Msgf("no MsgID %s found for this message", wrappedMsg.MsgID)
+		c.logger.Debug().Msgf("no MsgID %s found for this message", wrappedMsg.MessageType)
+		_ = stream.Reset()
+		return
+	}
+
+	c.streamMgr.AddStream(wrappedMsg.MsgID, stream)
+
+	msg := &Message{
+		PeerID:  stream.Conn().RemotePeer(),
+		Payload: payload,
+	}
+
+	select {
+	case channel <- msg:
+		// all good, message sent
+	case <-time.After(timeout):
+		// Note that we aren't logging payload itself
+		// as it might contain sensitive information
+		c.logger.Warn().
+			Str(logs.MsgID, wrappedMsg.MsgID).
+			Str(logs.Peer, peerID).
+			Str("protocol", string(stream.Protocol())).
+			Str("message_type", wrappedMsg.MessageType.String()).
+			Int("message_payload_bytes", len(wrappedMsg.Payload)).
+			Float64("timeout", timeout.Seconds()).
+			Msg("readFromStream: timeout to send message to channel")
 	}
 }
 
 func (c *Communication) handleStream(stream network.Stream) {
-	peerID := stream.Conn().RemotePeer().String()
-	c.logger.Debug().Msgf("handle stream from peer: %s", peerID)
-	// we will read from that stream
-	c.readFromStream(stream)
+	select {
+	case <-c.stopChan:
+		return
+	default:
+		c.readFromStream(stream)
+	}
 }
 
 func (c *Communication) bootStrapConnectivityCheck() error {

tss/keysign.go

@@ -203,7 +203,7 @@ func (t *Server) generateSignature(
 	// the statistic of keygen only care about Tss it self, even if the following http response aborts,
 	// it still counted as a successful keygen as the Tss model runs successfully.
 	if err != nil {
-		t.logger.Error().Err(err).Msg("err in keysign")
+		t.logger.Error().Err(err).Msg("SignMessage failed")
 		sigChan <- "signature generated"
 		t.broadcastKeysignFailure(msgID, allPeersID)
 		blameNodes := *blameMgr.GetBlame()
@@ -237,7 +237,10 @@ func (t *Server) KeySign(req keysign.Request) (keysign.Response, error) {
 		return emptyResp, err
 	}
 
-	t.logger.Info().Str(logs.MsgID, msgID).Any("request", req).Msg("Keysign request")
+	t.logger.Info().
+		Str(logs.MsgID, msgID).
+		Object("request", &req).
+		Msg("Keysign request")
 
 	var keysignInstance keysign.TssKeySign
 	var algo common.Algo