Merge pull request #147 from ava-labs/less-logs

Lower low level for many messages to improve UX. Improve wording of some messages.
This commit is contained in:
Stephen Buttolph 2020-05-12 14:38:02 -04:00 committed by GitHub
commit df786101a5
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
9 changed files with 89 additions and 86 deletions

View File

@ -209,7 +209,7 @@ func (nm *Handshake) ConnectTo(peer salticidae.PeerID, stakerID ids.ShortID, add
return return
} }
nm.log.Info("Attempting to connect to %s", stakerID) nm.log.Debug("attempting to connect to %s", stakerID)
nm.net.AddPeer(peer) nm.net.AddPeer(peer)
nm.net.SetPeerAddr(peer, addr) nm.net.SetPeerAddr(peer, addr)
@ -239,7 +239,7 @@ func (nm *Handshake) Connect(addr salticidae.NetAddr) {
} }
if !nm.enableStaking { if !nm.enableStaking {
nm.log.Info("Adding peer %s", ip) nm.log.Debug("adding peer %s", ip)
peer := salticidae.NewPeerIDFromNetAddr(addr, true) peer := salticidae.NewPeerIDFromNetAddr(addr, true)
nm.ConnectTo(peer, toShortID(ip), addr) nm.ConnectTo(peer, toShortID(ip), addr)
@ -254,7 +254,7 @@ func (nm *Handshake) Connect(addr salticidae.NetAddr) {
return return
} }
nm.log.Info("Adding peer %s", ip) nm.log.Debug("adding peer %s", ip)
count := new(int) count := new(int)
*count = 100 *count = 100
@ -281,7 +281,7 @@ func (nm *Handshake) Connect(addr salticidae.NetAddr) {
return return
} }
nm.log.Info("Attempting to discover peer at %s", ipStr) nm.log.Debug("attempting to discover peer at %s", ipStr)
msgNet := nm.net.AsMsgNetwork() msgNet := nm.net.AsMsgNetwork()
msgNet.Connect(addr) msgNet.Connect(addr)
@ -374,7 +374,7 @@ func (nm *Handshake) SendVersion(peer salticidae.PeerID) error {
build := Builder{} build := Builder{}
v, err := build.Version(nm.networkID, nm.clock.Unix(), toIPDesc(nm.myAddr), ClientVersion) v, err := build.Version(nm.networkID, nm.clock.Unix(), toIPDesc(nm.myAddr), ClientVersion)
if err != nil { if err != nil {
return fmt.Errorf("packing Version failed due to %s", err) return fmt.Errorf("packing version failed due to: %w", err)
} }
nm.send(v, peer) nm.send(v, peer)
nm.numVersionSent.Inc() nm.numVersionSent.Inc()
@ -397,16 +397,16 @@ func (nm *Handshake) SendPeerList(peers ...salticidae.PeerID) error {
} }
if len(ipsToSend) == 0 { if len(ipsToSend) == 0 {
nm.log.Debug("No IPs to send to %d peer(s)", len(peers)) nm.log.Debug("no IPs to send to %d peer(s)", len(peers))
return nil return nil
} }
nm.log.Verbo("Sending %d ips to %d peer(s)", len(ipsToSend), len(peers)) nm.log.Verbo("sending %d ips to %d peer(s)", len(ipsToSend), len(peers))
build := Builder{} build := Builder{}
pl, err := build.PeerList(ipsToSend) pl, err := build.PeerList(ipsToSend)
if err != nil { if err != nil {
return fmt.Errorf("Packing Peerlist failed due to %w", err) return fmt.Errorf("packing peer list failed due to: %w", err)
} }
nm.send(pl, peers...) nm.send(pl, peers...)
nm.numPeerlistSent.Add(float64(len(peers))) nm.numPeerlistSent.Add(float64(len(peers)))
@ -449,7 +449,7 @@ func connHandler(_conn *C.struct_msgnetwork_conn_t, connected C.bool, _ unsafe.P
HandshakeNet.requestedTimeout.Remove(ipID) HandshakeNet.requestedTimeout.Remove(ipID)
if _, exists := HandshakeNet.requested[ipStr]; !exists { if _, exists := HandshakeNet.requested[ipStr]; !exists {
HandshakeNet.log.Debug("connHandler called with %s", ip) HandshakeNet.log.Debug("connHandler called with ip %s", ip)
return true return true
} }
delete(HandshakeNet.requested, ipStr) delete(HandshakeNet.requested, ipStr)
@ -476,7 +476,7 @@ func (nm *Handshake) connectedToPeer(conn *C.struct_peernetwork_conn_t, peer sal
cert = ids.NewShortID(key) cert = ids.NewShortID(key)
} }
nm.log.Debug("Connected to %s", cert) nm.log.Debug("connected to %s", cert)
nm.reconnectTimeout.Remove(peerID) nm.reconnectTimeout.Remove(peerID)
@ -494,10 +494,10 @@ func (nm *Handshake) disconnectedFromPeer(peer salticidae.PeerID) {
cert := ids.ShortID{} cert := ids.ShortID{}
if pendingCert, exists := nm.pending.GetID(peer); exists { if pendingCert, exists := nm.pending.GetID(peer); exists {
cert = pendingCert cert = pendingCert
nm.log.Info("Disconnected from pending peer %s", cert) nm.log.Debug("disconnected from pending peer %s", cert)
} else if connectedCert, exists := nm.connections.GetID(peer); exists { } else if connectedCert, exists := nm.connections.GetID(peer); exists {
cert = connectedCert cert = connectedCert
nm.log.Info("Disconnected from peer %s", cert) nm.log.Debug("disconnected from peer %s", cert)
} else { } else {
return return
} }
@ -537,29 +537,29 @@ func (nm *Handshake) disconnectedFromPeer(peer salticidae.PeerID) {
// checkCompatibility Check to make sure that the peer and I speak the same language. // checkCompatibility Check to make sure that the peer and I speak the same language.
func (nm *Handshake) checkCompatibility(peerVersion string) bool { func (nm *Handshake) checkCompatibility(peerVersion string) bool {
if !strings.HasPrefix(peerVersion, VersionPrefix) { if !strings.HasPrefix(peerVersion, VersionPrefix) {
nm.log.Warn("Peer attempted to connect with an invalid version prefix") nm.log.Debug("peer attempted to connect with an invalid version prefix")
return false return false
} }
peerVersion = peerVersion[len(VersionPrefix):] peerVersion = peerVersion[len(VersionPrefix):]
splitPeerVersion := strings.SplitN(peerVersion, VersionSeparator, 3) splitPeerVersion := strings.SplitN(peerVersion, VersionSeparator, 3)
if len(splitPeerVersion) != 3 { if len(splitPeerVersion) != 3 {
nm.log.Warn("Peer attempted to connect with an invalid number of subversions") nm.log.Debug("peer attempted to connect with an invalid number of subversions")
return false return false
} }
major, err := strconv.Atoi(splitPeerVersion[0]) major, err := strconv.Atoi(splitPeerVersion[0])
if err != nil { if err != nil {
nm.log.Warn("Peer attempted to connect with an invalid major version") nm.log.Debug("peer attempted to connect with an invalid major version")
return false return false
} }
minor, err := strconv.Atoi(splitPeerVersion[1]) minor, err := strconv.Atoi(splitPeerVersion[1])
if err != nil { if err != nil {
nm.log.Warn("Peer attempted to connect with an invalid minor version") nm.log.Debug("peer attempted to connect with an invalid minor version")
return false return false
} }
patch, err := strconv.Atoi(splitPeerVersion[2]) patch, err := strconv.Atoi(splitPeerVersion[2])
if err != nil { if err != nil {
nm.log.Warn("Peer attempted to connect with an invalid patch version") nm.log.Debug("peer attempted to connect with an invalid patch version")
return false return false
} }
@ -568,7 +568,7 @@ func (nm *Handshake) checkCompatibility(peerVersion string) bool {
// peers major version is too low // peers major version is too low
return false return false
case major > MajorVersion: case major > MajorVersion:
nm.log.Warn("Peer attempted to connect with a higher major version, this client may need to be updated") nm.log.Warn("peer attempted to connect with a higher major version, this client may need to be updated")
return false return false
} }
@ -577,12 +577,12 @@ func (nm *Handshake) checkCompatibility(peerVersion string) bool {
// peers minor version is too low // peers minor version is too low
return false return false
case minor > MinorVersion: case minor > MinorVersion:
nm.log.Warn("Peer attempted to connect with a higher minor version, this client may need to be updated") nm.log.Warn("peer attempted to connect with a higher minor version, this client may need to be updated")
return false return false
} }
if patch > PatchVersion { if patch > PatchVersion {
nm.log.Warn("Peer is connecting with a higher patch version, this client may need to be updated") nm.log.Warn("peer is connecting with a higher patch version, this client may need to be updated")
} }
return true return true
} }
@ -612,7 +612,7 @@ func unknownPeerHandler(_addr *C.netaddr_t, _cert *C.x509_t, _ unsafe.Pointer) {
addr := salticidae.NetAddrFromC(salticidae.CNetAddr(_addr)).Copy(true) addr := salticidae.NetAddrFromC(salticidae.CNetAddr(_addr)).Copy(true)
ip := toIPDesc(addr) ip := toIPDesc(addr)
HandshakeNet.log.Info("Adding peer %s", ip) HandshakeNet.log.Debug("adding peer at %s", ip)
var peer salticidae.PeerID var peer salticidae.PeerID
var id ids.ShortID var id ids.ShortID
@ -685,7 +685,7 @@ func version(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.P
id, exists := HandshakeNet.pending.GetID(peer) id, exists := HandshakeNet.pending.GetID(peer)
if !exists { if !exists {
HandshakeNet.log.Warn("Dropping Version message because the peer isn't pending") HandshakeNet.log.Debug("dropping Version message because the peer isn't pending")
return return
} }
HandshakeNet.pending.Remove(peer, id) HandshakeNet.pending.Remove(peer, id)
@ -693,14 +693,14 @@ func version(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.P
build := Builder{} build := Builder{}
pMsg, err := build.Parse(Version, msg.GetPayloadByMove()) pMsg, err := build.Parse(Version, msg.GetPayloadByMove())
if err != nil { if err != nil {
HandshakeNet.log.Warn("Failed to parse Version message") HandshakeNet.log.Debug("failed to parse Version message")
HandshakeNet.net.DelPeer(peer) HandshakeNet.net.DelPeer(peer)
return return
} }
if networkID := pMsg.Get(NetworkID).(uint32); networkID != HandshakeNet.networkID { if networkID := pMsg.Get(NetworkID).(uint32); networkID != HandshakeNet.networkID {
HandshakeNet.log.Warn("Peer's network ID doesn't match our networkID: Peer's = %d ; Ours = %d", networkID, HandshakeNet.networkID) HandshakeNet.log.Debug("peer's network ID doesn't match our networkID: Peer's = %d ; Ours = %d", networkID, HandshakeNet.networkID)
HandshakeNet.net.DelPeer(peer) HandshakeNet.net.DelPeer(peer)
return return
@ -708,14 +708,14 @@ func version(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.P
myTime := float64(HandshakeNet.clock.Unix()) myTime := float64(HandshakeNet.clock.Unix())
if peerTime := float64(pMsg.Get(MyTime).(uint64)); math.Abs(peerTime-myTime) > MaxClockDifference.Seconds() { if peerTime := float64(pMsg.Get(MyTime).(uint64)); math.Abs(peerTime-myTime) > MaxClockDifference.Seconds() {
HandshakeNet.log.Warn("Peer's clock is too far out of sync with mine. His = %d, Mine = %d (seconds)", uint64(peerTime), uint64(myTime)) HandshakeNet.log.Debug("peer's clock is too far out of sync with mine. Peer's = %d, Ours = %d (seconds)", uint64(peerTime), uint64(myTime))
HandshakeNet.net.DelPeer(peer) HandshakeNet.net.DelPeer(peer)
return return
} }
if peerVersion := pMsg.Get(VersionStr).(string); !HandshakeNet.checkCompatibility(peerVersion) { if peerVersion := pMsg.Get(VersionStr).(string); !HandshakeNet.checkCompatibility(peerVersion) {
HandshakeNet.log.Debug("Dropping connection due to an incompatible version from peer") HandshakeNet.log.Debug("peer version, %s, is not compatible. dropping connection.", peerVersion)
HandshakeNet.net.DelPeer(peer) HandshakeNet.net.DelPeer(peer)
return return
@ -774,7 +774,7 @@ func peerList(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.
build := Builder{} build := Builder{}
pMsg, err := build.Parse(PeerList, msg.GetPayloadByMove()) pMsg, err := build.Parse(PeerList, msg.GetPayloadByMove())
if err != nil { if err != nil {
HandshakeNet.log.Warn("Failed to parse PeerList message due to %s", err) HandshakeNet.log.Debug("failed to parse PeerList message due to %s", err)
// TODO: What should we do here? // TODO: What should we do here?
return return
} }

View File

@ -109,7 +109,7 @@ func (s *Voting) GetAcceptedFrontier(validatorIDs ids.ShortSet, chainID ids.ID,
peers = append(peers, peer) peers = append(peers, peer)
s.log.Verbo("Sending a GetAcceptedFrontier to %s", vID) s.log.Verbo("Sending a GetAcceptedFrontier to %s", vID)
} else { } else {
s.log.Debug("Attempted to send a GetAcceptedFrontier message to a disconnected validator: %s", vID) s.log.Debug("attempted to send a GetAcceptedFrontier message to a disconnected validator: %s", vID)
s.executor.Add(func() { s.router.GetAcceptedFrontierFailed(vID, chainID, requestID) }) s.executor.Add(func() { s.router.GetAcceptedFrontierFailed(vID, chainID, requestID) })
} }
} }
@ -134,14 +134,14 @@ func (s *Voting) GetAcceptedFrontier(validatorIDs ids.ShortSet, chainID ids.ID,
func (s *Voting) AcceptedFrontier(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerIDs ids.Set) { func (s *Voting) AcceptedFrontier(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerIDs ids.Set) {
peer, exists := s.conns.GetPeerID(validatorID) peer, exists := s.conns.GetPeerID(validatorID)
if !exists { if !exists {
s.log.Debug("Attempted to send an AcceptedFrontier message to a disconnected validator: %s", validatorID) s.log.Debug("attempted to send an AcceptedFrontier message to disconnected validator: %s", validatorID)
return // Validator is not connected return // Validator is not connected
} }
build := Builder{} build := Builder{}
msg, err := build.AcceptedFrontier(chainID, requestID, containerIDs) msg, err := build.AcceptedFrontier(chainID, requestID, containerIDs)
if err != nil { if err != nil {
s.log.Error("Attempted to pack too large of an AcceptedFrontier message.\nNumber of containerIDs: %d", containerIDs.Len()) s.log.Error("attempted to pack too large of an AcceptedFrontier message.\nNumber of containerIDs: %d", containerIDs.Len())
return // Packing message failed return // Packing message failed
} }
@ -167,9 +167,9 @@ func (s *Voting) GetAccepted(validatorIDs ids.ShortSet, chainID ids.ID, requestI
vID := validatorID vID := validatorID
if peer, exists := s.conns.GetPeerID(validatorID); exists { if peer, exists := s.conns.GetPeerID(validatorID); exists {
peers = append(peers, peer) peers = append(peers, peer)
s.log.Verbo("Sending a GetAccepted to %s", vID) s.log.Verbo("sending a GetAccepted to %s", vID)
} else { } else {
s.log.Debug("Attempted to send a GetAccepted message to a disconnected validator: %s", vID) s.log.Debug("attempted to send a GetAccepted message to a disconnected validator: %s", vID)
s.executor.Add(func() { s.router.GetAcceptedFailed(vID, chainID, requestID) }) s.executor.Add(func() { s.router.GetAcceptedFailed(vID, chainID, requestID) })
} }
} }
@ -182,7 +182,7 @@ func (s *Voting) GetAccepted(validatorIDs ids.ShortSet, chainID ids.ID, requestI
s.executor.Add(func() { s.router.GetAcceptedFailed(validatorID, chainID, requestID) }) s.executor.Add(func() { s.router.GetAcceptedFailed(validatorID, chainID, requestID) })
} }
} }
s.log.Debug("Attempted to pack too large of a GetAccepted message.\nNumber of containerIDs: %d", containerIDs.Len()) s.log.Debug("attempted to pack too large of a GetAccepted message.\nNumber of containerIDs: %d", containerIDs.Len())
return // Packing message failed return // Packing message failed
} }
@ -204,14 +204,14 @@ func (s *Voting) GetAccepted(validatorIDs ids.ShortSet, chainID ids.ID, requestI
func (s *Voting) Accepted(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerIDs ids.Set) { func (s *Voting) Accepted(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerIDs ids.Set) {
peer, exists := s.conns.GetPeerID(validatorID) peer, exists := s.conns.GetPeerID(validatorID)
if !exists { if !exists {
s.log.Debug("Attempted to send an Accepted message to a disconnected validator: %s", validatorID) s.log.Debug("attempted to send an Accepted message to a disconnected validator: %s", validatorID)
return // Validator is not connected return // Validator is not connected
} }
build := Builder{} build := Builder{}
msg, err := build.Accepted(chainID, requestID, containerIDs) msg, err := build.Accepted(chainID, requestID, containerIDs)
if err != nil { if err != nil {
s.log.Error("Attempted to pack too large of an Accepted message.\nNumber of containerIDs: %d", containerIDs.Len()) s.log.Error("attempted to pack too large of an Accepted message.\nNumber of containerIDs: %d", containerIDs.Len())
return // Packing message failed return // Packing message failed
} }
@ -233,7 +233,7 @@ func (s *Voting) Accepted(validatorID ids.ShortID, chainID ids.ID, requestID uin
func (s *Voting) Get(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerID ids.ID) { func (s *Voting) Get(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerID ids.ID) {
peer, exists := s.conns.GetPeerID(validatorID) peer, exists := s.conns.GetPeerID(validatorID)
if !exists { if !exists {
s.log.Debug("Attempted to send a Get message to a disconnected validator: %s", validatorID) s.log.Debug("attempted to send a Get message to a disconnected validator: %s", validatorID)
s.executor.Add(func() { s.router.GetFailed(validatorID, chainID, requestID, containerID) }) s.executor.Add(func() { s.router.GetFailed(validatorID, chainID, requestID, containerID) })
return // Validator is not connected return // Validator is not connected
} }
@ -260,14 +260,14 @@ func (s *Voting) Get(validatorID ids.ShortID, chainID ids.ID, requestID uint32,
func (s *Voting) Put(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerID ids.ID, container []byte) { func (s *Voting) Put(validatorID ids.ShortID, chainID ids.ID, requestID uint32, containerID ids.ID, container []byte) {
peer, exists := s.conns.GetPeerID(validatorID) peer, exists := s.conns.GetPeerID(validatorID)
if !exists { if !exists {
s.log.Debug("Attempted to send a Container message to a disconnected validator: %s", validatorID) s.log.Debug("attempted to send a Container message to a disconnected validator: %s", validatorID)
return // Validator is not connected return // Validator is not connected
} }
build := Builder{} build := Builder{}
msg, err := build.Put(chainID, requestID, containerID, container) msg, err := build.Put(chainID, requestID, containerID, container)
if err != nil { if err != nil {
s.log.Error("Attempted to pack too large of a Put message.\nContainer length: %d", len(container)) s.log.Error("attempted to pack too large of a Put message.\nContainer length: %d", len(container))
return // Packing message failed return // Packing message failed
} }
@ -297,7 +297,7 @@ func (s *Voting) PushQuery(validatorIDs ids.ShortSet, chainID ids.ID, requestID
peers = append(peers, peer) peers = append(peers, peer)
s.log.Verbo("Sending a PushQuery to %s", vID) s.log.Verbo("Sending a PushQuery to %s", vID)
} else { } else {
s.log.Debug("Attempted to send a PushQuery message to a disconnected validator: %s", vID) s.log.Debug("attempted to send a PushQuery message to a disconnected validator: %s", vID)
s.executor.Add(func() { s.router.QueryFailed(vID, chainID, requestID) }) s.executor.Add(func() { s.router.QueryFailed(vID, chainID, requestID) })
} }
} }
@ -310,7 +310,7 @@ func (s *Voting) PushQuery(validatorIDs ids.ShortSet, chainID ids.ID, requestID
s.executor.Add(func() { s.router.QueryFailed(validatorID, chainID, requestID) }) s.executor.Add(func() { s.router.QueryFailed(validatorID, chainID, requestID) })
} }
} }
s.log.Error("Attempted to pack too large of a PushQuery message.\nContainer length: %d", len(container)) s.log.Error("attempted to pack too large of a PushQuery message.\nContainer length: %d", len(container))
return // Packing message failed return // Packing message failed
} }
@ -340,7 +340,7 @@ func (s *Voting) PullQuery(validatorIDs ids.ShortSet, chainID ids.ID, requestID
peers = append(peers, peer) peers = append(peers, peer)
s.log.Verbo("Sending a PullQuery to %s", vID) s.log.Verbo("Sending a PullQuery to %s", vID)
} else { } else {
s.log.Warn("Attempted to send a PullQuery message to a disconnected validator: %s", vID) s.log.Debug("attempted to send a PullQuery message to a disconnected validator: %s", vID)
s.executor.Add(func() { s.router.QueryFailed(vID, chainID, requestID) }) s.executor.Add(func() { s.router.QueryFailed(vID, chainID, requestID) })
} }
} }
@ -367,14 +367,14 @@ func (s *Voting) PullQuery(validatorIDs ids.ShortSet, chainID ids.ID, requestID
func (s *Voting) Chits(validatorID ids.ShortID, chainID ids.ID, requestID uint32, votes ids.Set) { func (s *Voting) Chits(validatorID ids.ShortID, chainID ids.ID, requestID uint32, votes ids.Set) {
peer, exists := s.conns.GetPeerID(validatorID) peer, exists := s.conns.GetPeerID(validatorID)
if !exists { if !exists {
s.log.Debug("Attempted to send a Chits message to a disconnected validator: %s", validatorID) s.log.Debug("attempted to send a Chits message to a disconnected validator: %s", validatorID)
return // Validator is not connected return // Validator is not connected
} }
build := Builder{} build := Builder{}
msg, err := build.Chits(chainID, requestID, votes) msg, err := build.Chits(chainID, requestID, votes)
if err != nil { if err != nil {
s.log.Error("Attempted to pack too large of a Chits message.\nChits length: %d", votes.Len()) s.log.Error("attempted to pack too large of a Chits message.\nChits length: %d", votes.Len())
return // Packing message failed return // Packing message failed
} }
@ -395,7 +395,7 @@ func (s *Voting) Chits(validatorID ids.ShortID, chainID ids.ID, requestID uint32
// Gossip attempts to gossip the container to the network // Gossip attempts to gossip the container to the network
func (s *Voting) Gossip(chainID, containerID ids.ID, container []byte) { func (s *Voting) Gossip(chainID, containerID ids.ID, container []byte) {
if err := s.gossip(chainID, containerID, container); err != nil { if err := s.gossip(chainID, containerID, container); err != nil {
s.log.Error("Error gossiping container %s to %s\n%s", containerID, chainID, err) s.log.Error("error gossiping container %s to %s: %s", containerID, chainID, err)
} }
} }
@ -433,7 +433,7 @@ func (s *Voting) gossip(chainID, containerID ids.ID, container []byte) error {
build := Builder{} build := Builder{}
msg, err := build.Put(chainID, math.MaxUint32, containerID, container) msg, err := build.Put(chainID, math.MaxUint32, containerID, container)
if err != nil { if err != nil {
return fmt.Errorf("Attempted to pack too large of a Put message.\nContainer length: %d: %w", len(container), err) return fmt.Errorf("attempted to pack too large of a Put message.\nContainer length: %d", len(container))
} }
s.log.Verbo("Sending a Put message to peers."+ s.log.Verbo("Sending a Put message to peers."+
@ -459,7 +459,7 @@ func getAcceptedFrontier(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t
validatorID, chainID, requestID, _, err := VotingNet.sanitize(_msg, _conn, GetAcceptedFrontier) validatorID, chainID, requestID, _, err := VotingNet.sanitize(_msg, _conn, GetAcceptedFrontier)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize getAcceptedFrontier message due to: %s", err)
return return
} }
@ -473,7 +473,7 @@ func acceptedFrontier(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, AcceptedFrontier) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, AcceptedFrontier)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize acceptedFrontier message due to: %s", err)
return return
} }
@ -481,7 +481,7 @@ func acceptedFrontier(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _
for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) {
containerID, err := ids.ToID(containerIDBytes) containerID, err := ids.ToID(containerIDBytes)
if err != nil { if err != nil {
VotingNet.log.Warn("Error parsing ContainerID: %v", containerIDBytes) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err)
return return
} }
containerIDs.Add(containerID) containerIDs.Add(containerID)
@ -497,7 +497,7 @@ func getAccepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsa
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, GetAccepted) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, GetAccepted)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize getAccepted message due to: %s", err)
return return
} }
@ -505,7 +505,7 @@ func getAccepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsa
for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) {
containerID, err := ids.ToID(containerIDBytes) containerID, err := ids.ToID(containerIDBytes)
if err != nil { if err != nil {
VotingNet.log.Warn("Error parsing ContainerID: %v", containerIDBytes) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err)
return return
} }
containerIDs.Add(containerID) containerIDs.Add(containerID)
@ -521,7 +521,7 @@ func accepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Accepted) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Accepted)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize accepted message due to: %s", err)
return return
} }
@ -529,7 +529,7 @@ func accepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.
for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) {
containerID, err := ids.ToID(containerIDBytes) containerID, err := ids.ToID(containerIDBytes)
if err != nil { if err != nil {
VotingNet.log.Warn("Error parsing ContainerID: %v", containerIDBytes) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err)
return return
} }
containerIDs.Add(containerID) containerIDs.Add(containerID)
@ -545,7 +545,7 @@ func get(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Point
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Get) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Get)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize get message due to: %s", err)
return return
} }
@ -561,7 +561,7 @@ func put(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Point
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Put) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Put)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize put message due to: %s", err)
return return
} }
@ -579,7 +579,7 @@ func pushQuery(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, PushQuery) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, PushQuery)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize pushQuery message due to: %s", err)
return return
} }
@ -597,7 +597,7 @@ func pullQuery(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, PullQuery) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, PullQuery)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize pullQuery message due to: %s", err)
return return
} }
@ -613,7 +613,7 @@ func chits(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Poi
validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Chits) validatorID, chainID, requestID, msg, err := VotingNet.sanitize(_msg, _conn, Chits)
if err != nil { if err != nil {
VotingNet.log.Error("Failed to sanitize message due to: %s", err) VotingNet.log.Debug("failed to sanitize chits message due to: %s", err)
return return
} }
@ -621,7 +621,7 @@ func chits(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Poi
for _, voteBytes := range msg.Get(ContainerIDs).([][]byte) { for _, voteBytes := range msg.Get(ContainerIDs).([][]byte) {
vote, err := ids.ToID(voteBytes) vote, err := ids.ToID(voteBytes)
if err != nil { if err != nil {
VotingNet.log.Warn("Error parsing chit: %v", voteBytes) VotingNet.log.Debug("error parsing chit %v: %s", voteBytes, err)
return return
} }
votes.Add(vote) votes.Add(vote)
@ -637,16 +637,16 @@ func (s *Voting) sanitize(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_
validatorID, exists := s.conns.GetID(peer) validatorID, exists := s.conns.GetID(peer)
if !exists { if !exists {
return ids.ShortID{}, ids.ID{}, 0, nil, fmt.Errorf("message received from an un-registered peer") return ids.ShortID{}, ids.ID{}, 0, nil, fmt.Errorf("received message from un-registered peer %s", validatorID)
} }
s.log.Verbo("Receiving message from %s", validatorID) s.log.Verbo("received message from %s", validatorID)
msg := salticidae.MsgFromC(salticidae.CMsg(_msg)) msg := salticidae.MsgFromC(salticidae.CMsg(_msg))
codec := Codec{} codec := Codec{}
pMsg, err := codec.Parse(op, msg.GetPayloadByMove()) pMsg, err := codec.Parse(op, msg.GetPayloadByMove())
if err != nil { if err != nil {
return ids.ShortID{}, ids.ID{}, 0, nil, err // The message couldn't be parsed return ids.ShortID{}, ids.ID{}, 0, nil, fmt.Errorf("couldn't parse payload: %w", err) // The message couldn't be parsed
} }
chainID, err := ids.ToID(pMsg.Get(ChainID).([]byte)) chainID, err := ids.ToID(pMsg.Get(ChainID).([]byte))

View File

@ -96,7 +96,7 @@ func (b *bootstrapper) Put(vdr ids.ShortID, requestID uint32, vtxID ids.ID, vtxB
vtx, err := b.State.ParseVertex(vtxBytes) vtx, err := b.State.ParseVertex(vtxBytes)
if err != nil { if err != nil {
b.BootstrapConfig.Context.Log.Warn("ParseVertex failed due to %s for block:\n%s", b.BootstrapConfig.Context.Log.Debug("ParseVertex failed due to %s for block:\n%s",
err, err,
formatting.DumpBytes{Bytes: vtxBytes}) formatting.DumpBytes{Bytes: vtxBytes})
b.GetFailed(vdr, requestID, vtxID) b.GetFailed(vdr, requestID, vtxID)

View File

@ -60,6 +60,8 @@ func (t *Transitive) finishBootstrapping() {
} }
t.Consensus.Initialize(t.Config.Context, t.Params, frontier) t.Consensus.Initialize(t.Config.Context, t.Params, frontier)
t.bootstrapped = true t.bootstrapped = true
t.Config.Context.Log.Info("Bootstrapping finished with %d vertices in the accepted frontier", len(frontier))
} }
// Gossip implements the Engine interface // Gossip implements the Engine interface
@ -110,7 +112,7 @@ func (t *Transitive) Put(vdr ids.ShortID, requestID uint32, vtxID ids.ID, vtxByt
vtx, err := t.Config.State.ParseVertex(vtxBytes) vtx, err := t.Config.State.ParseVertex(vtxBytes)
if err != nil { if err != nil {
t.Config.Context.Log.Warn("ParseVertex failed due to %s for block:\n%s", t.Config.Context.Log.Debug("ParseVertex failed due to %s for block:\n%s",
err, err,
formatting.DumpBytes{Bytes: vtxBytes}) formatting.DumpBytes{Bytes: vtxBytes})
t.GetFailed(vdr, requestID, vtxID) t.GetFailed(vdr, requestID, vtxID)
@ -178,7 +180,7 @@ func (t *Transitive) PushQuery(vdr ids.ShortID, requestID uint32, vtxID ids.ID,
// Chits implements the Engine interface // Chits implements the Engine interface
func (t *Transitive) Chits(vdr ids.ShortID, requestID uint32, votes ids.Set) { func (t *Transitive) Chits(vdr ids.ShortID, requestID uint32, votes ids.Set) {
if !t.bootstrapped { if !t.bootstrapped {
t.Config.Context.Log.Warn("Dropping Chits due to bootstrapping") t.Config.Context.Log.Debug("Dropping Chits due to bootstrapping")
return return
} }

View File

@ -122,9 +122,9 @@ func (b *Bootstrapper) Accepted(validatorID ids.ShortID, requestID uint32, conta
} }
if size := accepted.Len(); size == 0 && b.Config.Beacons.Len() > 0 { if size := accepted.Len(); size == 0 && b.Config.Beacons.Len() > 0 {
b.Context.Log.Warn("Bootstrapping finished with no accepted frontier. This is likely a result of failing to be able to connect to the specified bootstraps, or no transactions have been issued on this network yet") b.Context.Log.Warn("Bootstrapping finished with no accepted frontier. This is likely a result of failing to be able to connect to the specified bootstraps, or no transactions have been issued on this chain yet")
} else { } else {
b.Context.Log.Info("Bootstrapping finished with %d vertices in the accepted frontier", size) b.Context.Log.Info("Bootstrapping started syncing with %d vertices in the accepted frontier", size)
} }
b.Bootstrapable.ForceAccepted(accepted) b.Bootstrapable.ForceAccepted(accepted)

View File

@ -90,7 +90,7 @@ func (b *bootstrapper) Put(vdr ids.ShortID, requestID uint32, blkID ids.ID, blkB
blk, err := b.VM.ParseBlock(blkBytes) blk, err := b.VM.ParseBlock(blkBytes)
if err != nil { if err != nil {
b.BootstrapConfig.Context.Log.Warn("ParseBlock failed due to %s for block:\n%s", b.BootstrapConfig.Context.Log.Debug("ParseBlock failed due to %s for block:\n%s",
err, err,
formatting.DumpBytes{Bytes: blkBytes}) formatting.DumpBytes{Bytes: blkBytes})
b.GetFailed(vdr, requestID, blkID) b.GetFailed(vdr, requestID, blkID)

View File

@ -63,6 +63,8 @@ func (t *Transitive) finishBootstrapping() {
default: default:
t.Config.VM.SetPreference(tailID) t.Config.VM.SetPreference(tailID)
} }
t.Config.Context.Log.Info("Bootstrapping finished with %s as the last accepted block", tailID)
} }
// Gossip implements the Engine interface // Gossip implements the Engine interface
@ -105,7 +107,7 @@ func (t *Transitive) Put(vdr ids.ShortID, requestID uint32, blkID ids.ID, blkByt
blk, err := t.Config.VM.ParseBlock(blkBytes) blk, err := t.Config.VM.ParseBlock(blkBytes)
if err != nil { if err != nil {
t.Config.Context.Log.Warn("ParseBlock failed due to %s for block:\n%s", t.Config.Context.Log.Debug("ParseBlock failed due to %s for block:\n%s",
err, err,
formatting.DumpBytes{Bytes: blkBytes}) formatting.DumpBytes{Bytes: blkBytes})
t.GetFailed(vdr, requestID, blkID) t.GetFailed(vdr, requestID, blkID)
@ -165,13 +167,13 @@ func (t *Transitive) PushQuery(vdr ids.ShortID, requestID uint32, blkID ids.ID,
// Chits implements the Engine interface // Chits implements the Engine interface
func (t *Transitive) Chits(vdr ids.ShortID, requestID uint32, votes ids.Set) { func (t *Transitive) Chits(vdr ids.ShortID, requestID uint32, votes ids.Set) {
if !t.bootstrapped { if !t.bootstrapped {
t.Config.Context.Log.Warn("Dropping Chits due to bootstrapping") t.Config.Context.Log.Debug("Dropping Chits due to bootstrapping")
return return
} }
// Since this is snowman, there should only be one ID in the vote set // Since this is snowman, there should only be one ID in the vote set
if votes.Len() != 1 { if votes.Len() != 1 {
t.Config.Context.Log.Warn("Chits was called with the wrong number of votes %d. ValidatorID: %s, RequestID: %d", votes.Len(), vdr, requestID) t.Config.Context.Log.Debug("Chits was called with the wrong number of votes %d. ValidatorID: %s, RequestID: %d", votes.Len(), vdr, requestID)
t.QueryFailed(vdr, requestID) t.QueryFailed(vdr, requestID)
return return
} }

View File

@ -50,7 +50,7 @@ func (sr *ChainRouter) AddChain(chain *handler.Handler) {
defer sr.lock.Unlock() defer sr.lock.Unlock()
chainID := chain.Context().ChainID chainID := chain.Context().ChainID
sr.log.Debug("Adding %s to the routing table", chainID) sr.log.Debug("registering chain %s with chain router", chainID)
sr.chains[chainID.Key()] = chain sr.chains[chainID.Key()] = chain
} }
@ -64,7 +64,7 @@ func (sr *ChainRouter) RemoveChain(chainID ids.ID) {
chain.Shutdown() chain.Shutdown()
delete(sr.chains, chainID.Key()) delete(sr.chains, chainID.Key())
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -78,7 +78,7 @@ func (sr *ChainRouter) GetAcceptedFrontier(validatorID ids.ShortID, chainID ids.
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.GetAcceptedFrontier(validatorID, requestID) chain.GetAcceptedFrontier(validatorID, requestID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -93,7 +93,7 @@ func (sr *ChainRouter) AcceptedFrontier(validatorID ids.ShortID, chainID ids.ID,
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.AcceptedFrontier(validatorID, requestID, containerIDs) chain.AcceptedFrontier(validatorID, requestID, containerIDs)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -108,7 +108,7 @@ func (sr *ChainRouter) GetAcceptedFrontierFailed(validatorID ids.ShortID, chainI
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.GetAcceptedFrontierFailed(validatorID, requestID) chain.GetAcceptedFrontierFailed(validatorID, requestID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -122,7 +122,7 @@ func (sr *ChainRouter) GetAccepted(validatorID ids.ShortID, chainID ids.ID, requ
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.GetAccepted(validatorID, requestID, containerIDs) chain.GetAccepted(validatorID, requestID, containerIDs)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -137,7 +137,7 @@ func (sr *ChainRouter) Accepted(validatorID ids.ShortID, chainID ids.ID, request
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.Accepted(validatorID, requestID, containerIDs) chain.Accepted(validatorID, requestID, containerIDs)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -152,7 +152,7 @@ func (sr *ChainRouter) GetAcceptedFailed(validatorID ids.ShortID, chainID ids.ID
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.GetAcceptedFailed(validatorID, requestID) chain.GetAcceptedFailed(validatorID, requestID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -165,7 +165,7 @@ func (sr *ChainRouter) Get(validatorID ids.ShortID, chainID ids.ID, requestID ui
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.Get(validatorID, requestID, containerID) chain.Get(validatorID, requestID, containerID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -181,7 +181,7 @@ func (sr *ChainRouter) Put(validatorID ids.ShortID, chainID ids.ID, requestID ui
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.Put(validatorID, requestID, containerID, container) chain.Put(validatorID, requestID, containerID, container)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -195,7 +195,7 @@ func (sr *ChainRouter) GetFailed(validatorID ids.ShortID, chainID ids.ID, reques
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.GetFailed(validatorID, requestID, containerID) chain.GetFailed(validatorID, requestID, containerID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -208,7 +208,7 @@ func (sr *ChainRouter) PushQuery(validatorID ids.ShortID, chainID ids.ID, reques
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.PushQuery(validatorID, requestID, containerID, container) chain.PushQuery(validatorID, requestID, containerID, container)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -221,7 +221,7 @@ func (sr *ChainRouter) PullQuery(validatorID ids.ShortID, chainID ids.ID, reques
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.PullQuery(validatorID, requestID, containerID) chain.PullQuery(validatorID, requestID, containerID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -236,7 +236,7 @@ func (sr *ChainRouter) Chits(validatorID ids.ShortID, chainID ids.ID, requestID
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.Chits(validatorID, requestID, votes) chain.Chits(validatorID, requestID, votes)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }
@ -250,7 +250,7 @@ func (sr *ChainRouter) QueryFailed(validatorID ids.ShortID, chainID ids.ID, requ
if chain, exists := sr.chains[chainID.Key()]; exists { if chain, exists := sr.chains[chainID.Key()]; exists {
chain.QueryFailed(validatorID, requestID) chain.QueryFailed(validatorID, requestID)
} else { } else {
sr.log.Warn("Message referenced a chain, %s, this validator is not validating", chainID) sr.log.Debug("message referenced a chain, %s, this node doesn't validate", chainID)
} }
} }

View File

@ -164,7 +164,6 @@ func (cb *CommonBlock) parentBlock() Block {
parentID := cb.ParentID() parentID := cb.ParentID()
parent, err := cb.vm.getBlock(parentID) parent, err := cb.vm.getBlock(parentID)
if err != nil { if err != nil {
cb.vm.Ctx.Log.Debug("could not get parent (ID %s) of block %s", parentID, cb.ID())
return nil return nil
} }
return parent.(Block) return parent.(Block)