From d2998e8c57fae0b55a3cf6a7ce80173ba4676446 Mon Sep 17 00:00:00 2001 From: Dan Laine Date: Fri, 22 May 2020 15:56:33 -0400 Subject: [PATCH 1/3] more verbose logging in voting handlers --- networking/voting_handlers.go | 34 ++++++++++++++++++++++++++++++---- 1 file changed, 30 insertions(+), 4 deletions(-) diff --git a/networking/voting_handlers.go b/networking/voting_handlers.go index 2c8dce6..76aed7d 100644 --- a/networking/voting_handlers.go +++ b/networking/voting_handlers.go @@ -462,6 +462,7 @@ func getAcceptedFrontier(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t VotingNet.log.Debug("failed to sanitize getAcceptedFrontier message due to: %s", err) return } + VotingNet.log.Verbo("received getAcceptedFrontier from %v\nchainID: %v\nrequestID: %v", validatorID, chainID, requestID) VotingNet.router.GetAcceptedFrontier(validatorID, chainID, requestID) } @@ -481,11 +482,13 @@ func acceptedFrontier(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { containerID, err := ids.ToID(containerIDBytes) if err != nil { + VotingNet.log.Verbo("received acceptedFrontier from %v\nchainID: %v\nrequestID: %v", validatorID, chainID, requestID) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err) return } containerIDs.Add(containerID) } + VotingNet.log.Verbo("received acceptedFrontier from %v\nchainID: %v\nrequestID: %v\ncontainerIDs: %v", validatorID, chainID, requestID, containerIDs) VotingNet.router.AcceptedFrontier(validatorID, chainID, requestID, containerIDs) } @@ -505,11 +508,13 @@ func getAccepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsa for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { containerID, err := ids.ToID(containerIDBytes) if err != nil { + VotingNet.log.Verbo("received getAccepted from %v\nchainID: %v\nrequestID: %v", validatorID, chainID, requestID) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err) return } containerIDs.Add(containerID) } + VotingNet.log.Verbo("received getAccepted from %v\nchainID: %v\nrequestID: %v\ncontainerIDs: %v", validatorID, chainID, requestID, containerIDs) VotingNet.router.GetAccepted(validatorID, chainID, requestID, containerIDs) } @@ -529,11 +534,13 @@ func accepted(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe. for _, containerIDBytes := range msg.Get(ContainerIDs).([][]byte) { containerID, err := ids.ToID(containerIDBytes) if err != nil { + VotingNet.log.Verbo("received accepted from %v\nchainID: %v\nrequestID: %v", validatorID, chainID, requestID) VotingNet.log.Debug("error parsing ContainerID %v: %s", containerIDBytes, err) return } containerIDs.Add(containerID) } + VotingNet.log.Verbo("received accepted from %v\nchainID: %v\nrequestID: %v\ncontainerIDs: %v", validatorID, chainID, requestID, containerIDs) VotingNet.router.Accepted(validatorID, chainID, requestID, containerIDs) } @@ -549,7 +556,12 @@ func get(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Point return } - containerID, _ := ids.ToID(msg.Get(ContainerID).([]byte)) + containerID, err := ids.ToID(msg.Get(ContainerID).([]byte)) + VotingNet.log.Verbo("received get from %v\nchainID: %v\nrequestID: %v\ncontainerID: %v", validatorID, chainID, requestID, ContainerID) + if err != nil { + VotingNet.log.Debug("error parsing ContainerID: %s", err) + return + } VotingNet.router.Get(validatorID, chainID, requestID, containerID) } @@ -565,7 +577,11 @@ func put(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Point return } - containerID, _ := ids.ToID(msg.Get(ContainerID).([]byte)) + containerID, err := ids.ToID(msg.Get(ContainerID).([]byte)) + VotingNet.log.Verbo("received put from %v\nchainID: %v\nrequestID: %v\ncontainerID: %v", validatorID, chainID, requestID, containerID) + if err != nil { + VotingNet.log.Debug("couldn't parse containerID") + } containerBytes := msg.Get(ContainerBytes).([]byte) @@ -583,7 +599,11 @@ func pushQuery(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe return } - containerID, _ := ids.ToID(msg.Get(ContainerID).([]byte)) + containerID, err := ids.ToID(msg.Get(ContainerID).([]byte)) + VotingNet.log.Verbo("received pushQuery from %v\nchainID: %v\nrequestID: %v\ncontainerID: %v", validatorID, chainID, requestID, containerID) + if err != nil { + VotingNet.log.Debug("couldn't parse containerID") + } containerBytes := msg.Get(ContainerBytes).([]byte) @@ -601,7 +621,11 @@ func pullQuery(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe return } - containerID, _ := ids.ToID(msg.Get(ContainerID).([]byte)) + containerID, err := ids.ToID(msg.Get(ContainerID).([]byte)) + VotingNet.log.Verbo("received pullQuery from %v\nchainID: %v\nrequestID: %v\ncontainerID: %v", validatorID, chainID, requestID, containerID) + if err != nil { + VotingNet.log.Verbo("couldn't parse containerID") + } VotingNet.router.PullQuery(validatorID, chainID, requestID, containerID) } @@ -621,11 +645,13 @@ func chits(_msg *C.struct_msg_t, _conn *C.struct_msgnetwork_conn_t, _ unsafe.Poi for _, voteBytes := range msg.Get(ContainerIDs).([][]byte) { vote, err := ids.ToID(voteBytes) if err != nil { + VotingNet.log.Verbo("received chits from %v\nchainID: %v\nrequestID: %v", validatorID, chainID, requestID) VotingNet.log.Debug("error parsing chit %v: %s", voteBytes, err) return } votes.Add(vote) } + VotingNet.log.Verbo("received chits from %v\nchainID: %v\nrequestID: %v\nvotes: %v", validatorID, chainID, requestID, votes) VotingNet.router.Chits(validatorID, chainID, requestID, votes) } From 0a28f16cbed72447cbb98c97b95765351b8541b8 Mon Sep 17 00:00:00 2001 From: Dan Laine Date: Fri, 22 May 2020 17:41:47 -0400 Subject: [PATCH 2/3] periodically print bootstrap progress to log. don't fetch ancestry of same vertex multiple times --- snow/engine/avalanche/bootstrapper.go | 32 +++++++++++++++++++++++---- 1 file changed, 28 insertions(+), 4 deletions(-) diff --git a/snow/engine/avalanche/bootstrapper.go b/snow/engine/avalanche/bootstrapper.go index 304172f..f348521 100644 --- a/snow/engine/avalanche/bootstrapper.go +++ b/snow/engine/avalanche/bootstrapper.go @@ -30,9 +30,16 @@ type bootstrapper struct { metrics common.Bootstrapper + // IDs of vertices that we're already in the process of getting + // TODO: Find a better way to track; this keeps every single vertex's ID in memory when bootstrapping from nothing + seen ids.Set + + numFetched uint64 // number of vertices that have been fetched from validators + // vtxReqs prevents asking validators for the same vertex vtxReqs common.Requests + // IDs of vertices that we have requested from other validators but haven't received pending ids.Set finished bool onFinished func() @@ -91,8 +98,6 @@ func (b *bootstrapper) ForceAccepted(acceptedContainerIDs ids.Set) { // Put ... func (b *bootstrapper) Put(vdr ids.ShortID, requestID uint32, vtxID ids.ID, vtxBytes []byte) { - b.BootstrapConfig.Context.Log.Verbo("Put called for vertexID %s", vtxID) - vtx, err := b.State.ParseVertex(vtxBytes) if err != nil { b.BootstrapConfig.Context.Log.Debug("ParseVertex failed due to %s for block:\n%s", @@ -168,6 +173,10 @@ func (b *bootstrapper) addVertex(vtx avalanche.Vertex) { func (b *bootstrapper) storeVertex(vtx avalanche.Vertex) { vts := []avalanche.Vertex{vtx} + b.numFetched++ + if b.numFetched%2500 == 0 { // perioidcally inform user of progress + b.BootstrapConfig.Context.Log.Info("bootstrapping has fetched %d vertices", b.numFetched) + } for len(vts) > 0 { newLen := len(vts) - 1 @@ -187,6 +196,8 @@ func (b *bootstrapper) storeVertex(vtx avalanche.Vertex) { vtx: vtx, }); err == nil { b.numBlockedVtx.Inc() + } else { + b.BootstrapConfig.Context.Log.Verbo("couldn't push to vtxBlocked") } for _, tx := range vtx.Txs() { if err := b.TxBlocked.Push(&txJob{ @@ -195,10 +206,20 @@ func (b *bootstrapper) storeVertex(vtx avalanche.Vertex) { tx: tx, }); err == nil { b.numBlockedTx.Inc() + } else { + b.BootstrapConfig.Context.Log.Verbo("couldn't push to txBlocked") } } - - vts = append(vts, vtx.Parents()...) + parentsToAdd := []avalanche.Vertex{} + parentsToAddIDs := ids.Set{} // ToDO remove...only here for debug + for _, parent := range vtx.Parents() { + if !b.seen.Contains(parent.ID()) { + parentsToAdd = append(parentsToAdd, parent) + parentsToAddIDs.Add(parent.ID()) + } + } + vts = append(vts, parentsToAdd...) + b.seen.Add(parentsToAddIDs.List()...) case choices.Accepted: b.BootstrapConfig.Context.Log.Verbo("Bootstrapping confirmed %s", vtxID) case choices.Rejected: @@ -214,12 +235,15 @@ func (b *bootstrapper) finish() { if b.finished { return } + b.BootstrapConfig.Context.Log.Info("bootstrapping finished fetching vertices. executing state transitions...") b.executeAll(b.TxBlocked, b.numBlockedTx) b.executeAll(b.VtxBlocked, b.numBlockedVtx) // Start consensus + b.BootstrapConfig.Context.Log.Info("done bootstrapping") b.onFinished() + b.seen = ids.Set{} b.finished = true } From 6071672e4d22fb4c86d573fd789dd5eb6d40654d Mon Sep 17 00:00:00 2001 From: StephenButtolph Date: Mon, 25 May 2020 22:18:43 -0400 Subject: [PATCH 3/3] minor code cleanup --- snow/engine/avalanche/bootstrapper.go | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/snow/engine/avalanche/bootstrapper.go b/snow/engine/avalanche/bootstrapper.go index f348521..ae3ec99 100644 --- a/snow/engine/avalanche/bootstrapper.go +++ b/snow/engine/avalanche/bootstrapper.go @@ -210,16 +210,12 @@ func (b *bootstrapper) storeVertex(vtx avalanche.Vertex) { b.BootstrapConfig.Context.Log.Verbo("couldn't push to txBlocked") } } - parentsToAdd := []avalanche.Vertex{} - parentsToAddIDs := ids.Set{} // ToDO remove...only here for debug for _, parent := range vtx.Parents() { - if !b.seen.Contains(parent.ID()) { - parentsToAdd = append(parentsToAdd, parent) - parentsToAddIDs.Add(parent.ID()) + if parentID := parent.ID(); !b.seen.Contains(parentID) { + b.seen.Add(parentID) + vts = append(vts, parent) } } - vts = append(vts, parentsToAdd...) - b.seen.Add(parentsToAddIDs.List()...) case choices.Accepted: b.BootstrapConfig.Context.Log.Verbo("Bootstrapping confirmed %s", vtxID) case choices.Rejected: @@ -241,7 +237,6 @@ func (b *bootstrapper) finish() { b.executeAll(b.VtxBlocked, b.numBlockedVtx) // Start consensus - b.BootstrapConfig.Context.Log.Info("done bootstrapping") b.onFinished() b.seen = ids.Set{} b.finished = true