fix: more logging replace

This commit is contained in:
Igor Sirotin 2025-10-01 10:28:41 +01:00
parent 7daed85191
commit aae1c44aca
No known key found for this signature in database
GPG Key ID: 0EABBCB40CB9AD4A
4 changed files with 27 additions and 26 deletions

View File

@ -20,12 +20,11 @@
package discover package discover
import ( import (
"fmt"
"net" "net"
"sort" "sort"
"time" "time"
"github.com/ethereum/go-ethereum/log" "go.uber.org/zap"
) )
const ( const (
@ -49,10 +48,10 @@ func checkClockDrift() {
return return
} }
if drift < -driftThreshold || drift > driftThreshold { if drift < -driftThreshold || drift > driftThreshold {
log.Warn(fmt.Sprintf("System clock seems off by %v, which can prevent network connectivity", drift)) zap.L().Warn("System clock seems off", zap.Duration("drift", drift))
log.Warn("Please enable network time synchronisation in system settings.") zap.L().Warn("Please enable network time synchronisation in system settings.")
} else { } else {
log.Debug("NTP sanity check done", "drift", drift) zap.L().Debug("NTP sanity check done", zap.Duration("drift", drift))
} }
} }

View File

@ -334,7 +334,7 @@ func (tab *Table) doRevalidate(done chan<- struct{}) {
// Ping the selected node and wait for a pong. // Ping the selected node and wait for a pong.
remoteSeq, err := tab.net.ping(unwrapNode(last)) remoteSeq, err := tab.net.ping(unwrapNode(last))
logger := tab.log.With(zap.String("id", last.ID().String()), zap.String("addr", last.addr().String())) logger := tab.log.With(zap.Stringer("id", last.ID()), zap.Stringer("addr", last.addr()))
// Also fetch record if the node replied and returned a higher sequence number. // Also fetch record if the node replied and returned a higher sequence number.
if last.Seq() < remoteSeq { if last.Seq() < remoteSeq {
@ -364,8 +364,8 @@ func (tab *Table) doRevalidate(done chan<- struct{}) {
if r := tab.replace(b, last); r != nil { if r := tab.replace(b, last); r != nil {
tab.log.Debug("Replaced dead node", tab.log.Debug("Replaced dead node",
zap.Uint("checks", last.livenessChecks), zap.Uint("checks", last.livenessChecks),
zap.String("r", r.ID().String()), zap.Stringer("r", r.ID()),
zap.String("rip", r.IP().String())) zap.Stringer("rip", r.IP()))
} else { } else {
tab.log.Debug("Removed dead node", tab.log.Debug("Removed dead node",
zap.Uint("checks", last.livenessChecks)) zap.Uint("checks", last.livenessChecks))

View File

@ -21,7 +21,8 @@ import (
"sync" "sync"
"time" "time"
"github.com/ethereum/go-ethereum/log" "go.uber.org/zap"
"github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/p2p/enode"
"github.com/waku-org/go-discover/discover/v5wire" "github.com/waku-org/go-discover/discover/v5wire"
) )
@ -95,7 +96,7 @@ func (t *talkSystem) handleRequest(id enode.ID, addr *net.UDPAddr, req *v5wire.T
case <-timeout.C: case <-timeout.C:
// Couldn't get it in time, drop the request. // Couldn't get it in time, drop the request.
if time.Since(t.lastLog) > 5*time.Second { if time.Since(t.lastLog) > 5*time.Second {
log.Warn("Dropping TALKREQ due to overload", "ndrop", t.dropCount) t.transport.log.Warn("Dropping TALKREQ due to overload", zap.Int("ndrop", t.dropCount))
t.lastLog = time.Now() t.lastLog = time.Now()
t.dropCount++ t.dropCount++
} }

View File

@ -29,11 +29,13 @@ import (
"sync" "sync"
"time" "time"
"go.uber.org/zap"
"github.com/ethereum/go-ethereum/common/mclock" "github.com/ethereum/go-ethereum/common/mclock"
"github.com/ethereum/go-ethereum/log"
"github.com/ethereum/go-ethereum/p2p/enode" "github.com/ethereum/go-ethereum/p2p/enode"
"github.com/ethereum/go-ethereum/p2p/enr" "github.com/ethereum/go-ethereum/p2p/enr"
"github.com/ethereum/go-ethereum/p2p/netutil" "github.com/ethereum/go-ethereum/p2p/netutil"
"github.com/waku-org/go-discover/discover/v5wire" "github.com/waku-org/go-discover/discover/v5wire"
) )
@ -67,7 +69,7 @@ type UDPv5 struct {
priv *ecdsa.PrivateKey priv *ecdsa.PrivateKey
localNode *enode.LocalNode localNode *enode.LocalNode
db *enode.DB db *enode.DB
log log.Logger log *zap.Logger
clock mclock.Clock clock mclock.Clock
validSchemes enr.IdentityScheme validSchemes enr.IdentityScheme
@ -404,7 +406,10 @@ func (t *UDPv5) waitForNodes(c *callV5, distances []uint) ([]*enode.Node, error)
for _, record := range response.Nodes { for _, record := range response.Nodes {
node, err := t.verifyResponseNode(c, record, distances, seen) node, err := t.verifyResponseNode(c, record, distances, seen)
if err != nil { if err != nil {
t.log.Debug("Invalid record in "+response.Name(), "id", c.node.ID(), "err", err) t.log.Debug("Invalid record in "+response.Name(),
zap.Stringer("id", c.node.ID()),
zap.Error(err),
)
continue continue
} }
nodes = append(nodes, node) nodes = append(nodes, node)
@ -649,12 +654,11 @@ func (t *UDPv5) send(toID enode.ID, toAddr *net.UDPAddr, packet v5wire.Packet, c
enc, nonce, err := t.codec.Encode(toID, addr, packet, c) enc, nonce, err := t.codec.Encode(toID, addr, packet, c)
if err != nil { if err != nil {
t.logcontext = append(t.logcontext, "err", err) t.logcontext = append(t.logcontext, "err", err)
t.log.Warn(">> "+packet.Name(), t.logcontext...) t.log.Warn(">> "+packet.Name(), zap.Any("context", t.logcontext))
return nonce, err return nonce, err
} }
_, err = t.conn.WriteToUDP(enc, toAddr) _, err = t.conn.WriteToUDP(enc, toAddr)
t.log.Trace(">> "+packet.Name(), t.logcontext...)
return nonce, err return nonce, err
} }
@ -667,12 +671,12 @@ func (t *UDPv5) readLoop() {
nbytes, from, err := t.conn.ReadFromUDP(buf) nbytes, from, err := t.conn.ReadFromUDP(buf)
if netutil.IsTemporaryError(err) { if netutil.IsTemporaryError(err) {
// Ignore temporary read errors. // Ignore temporary read errors.
t.log.Debug("Temporary UDP read error", "err", err) t.log.Debug("Temporary UDP read error", zap.Error(err))
continue continue
} else if err != nil { } else if err != nil {
// Shut down the loop for permanent errors. // Shut down the loop for permanent errors.
if !errors.Is(err, io.EOF) { if !errors.Is(err, io.EOF) {
t.log.Debug("UDP read error", "err", err) t.log.Debug("UDP read error", zap.Error(err))
} }
return return
} }
@ -697,13 +701,12 @@ func (t *UDPv5) handlePacket(rawpacket []byte, fromAddr *net.UDPAddr) error {
if err != nil { if err != nil {
if t.unhandled != nil && v5wire.IsInvalidHeader(err) { if t.unhandled != nil && v5wire.IsInvalidHeader(err) {
// The packet seems unrelated to discv5, send it to the next protocol. // The packet seems unrelated to discv5, send it to the next protocol.
// t.log.Trace("Unhandled discv5 packet", "id", fromID, "addr", addr, "err", err)
up := ReadPacket{Data: make([]byte, len(rawpacket)), Addr: fromAddr} up := ReadPacket{Data: make([]byte, len(rawpacket)), Addr: fromAddr}
copy(up.Data, rawpacket) copy(up.Data, rawpacket)
t.unhandled <- up t.unhandled <- up
return nil return nil
} }
t.log.Debug("Bad discv5 packet", "id", fromID, "addr", addr, "err", err) t.log.Debug("Bad discv5 packet", zap.Stringer("id", fromID), zap.Stringer("addr", fromAddr), zap.Error(err))
return err return err
} }
if fromNode != nil { if fromNode != nil {
@ -714,7 +717,6 @@ func (t *UDPv5) handlePacket(rawpacket []byte, fromAddr *net.UDPAddr) error {
// WHOAREYOU logged separately to report errors. // WHOAREYOU logged separately to report errors.
t.logcontext = append(t.logcontext[:0], "id", fromID, "addr", addr) t.logcontext = append(t.logcontext[:0], "id", fromID, "addr", addr)
t.logcontext = packet.AppendLogInfo(t.logcontext) t.logcontext = packet.AppendLogInfo(t.logcontext)
t.log.Trace("<< "+packet.Name(), t.logcontext...)
} }
t.handle(packet, fromID, fromAddr) t.handle(packet, fromID, fromAddr)
return nil return nil
@ -724,15 +726,15 @@ func (t *UDPv5) handlePacket(rawpacket []byte, fromAddr *net.UDPAddr) error {
func (t *UDPv5) handleCallResponse(fromID enode.ID, fromAddr *net.UDPAddr, p v5wire.Packet) bool { func (t *UDPv5) handleCallResponse(fromID enode.ID, fromAddr *net.UDPAddr, p v5wire.Packet) bool {
ac := t.activeCallByNode[fromID] ac := t.activeCallByNode[fromID]
if ac == nil || !bytes.Equal(p.RequestID(), ac.reqid) { if ac == nil || !bytes.Equal(p.RequestID(), ac.reqid) {
t.log.Debug(fmt.Sprintf("Unsolicited/late %s response", p.Name()), "id", fromID, "addr", fromAddr) t.log.Debug(fmt.Sprintf("Unsolicited/late %s response", p.Name()), zap.Stringer("id", fromID), zap.Stringer("addr", fromAddr))
return false return false
} }
if !fromAddr.IP.Equal(ac.addr.IP) || fromAddr.Port != ac.addr.Port { if !fromAddr.IP.Equal(ac.addr.IP) || fromAddr.Port != ac.addr.Port {
t.log.Debug(fmt.Sprintf("%s from wrong endpoint", p.Name()), "id", fromID, "addr", fromAddr) t.log.Debug(fmt.Sprintf("%s from wrong endpoint", p.Name()), zap.Stringer("id", fromID), zap.Stringer("addr", fromAddr))
return false return false
} }
if p.Kind() != ac.responseType { if p.Kind() != ac.responseType {
t.log.Debug(fmt.Sprintf("Wrong discv5 response type %s", p.Name()), "id", fromID, "addr", fromAddr) t.log.Debug(fmt.Sprintf("Wrong discv5 response type %s", p.Name()), zap.Stringer("id", fromID), zap.Stringer("addr", fromAddr))
return false return false
} }
t.startResponseTimeout(ac) t.startResponseTimeout(ac)
@ -796,18 +798,17 @@ var (
func (t *UDPv5) handleWhoareyou(p *v5wire.Whoareyou, fromID enode.ID, fromAddr *net.UDPAddr) { func (t *UDPv5) handleWhoareyou(p *v5wire.Whoareyou, fromID enode.ID, fromAddr *net.UDPAddr) {
c, err := t.matchWithCall(fromID, p.Nonce) c, err := t.matchWithCall(fromID, p.Nonce)
if err != nil { if err != nil {
t.log.Debug("Invalid "+p.Name(), "addr", fromAddr, "err", err) t.log.Debug("Invalid "+p.Name(), zap.String("addr", fromAddr.String()), zap.Error(err))
return return
} }
if c.node == nil { if c.node == nil {
// Can't perform handshake because we don't have the ENR. // Can't perform handshake because we don't have the ENR.
t.log.Debug("Can't handle "+p.Name(), "addr", fromAddr, "err", "call has no ENR") t.log.Debug("Can't handle "+p.Name(), zap.String("addr", fromAddr.String()), zap.Error(errors.New("call has no ENR")))
c.err <- errors.New("remote wants handshake, but call has no ENR") c.err <- errors.New("remote wants handshake, but call has no ENR")
return return
} }
// Resend the call that was answered by WHOAREYOU. // Resend the call that was answered by WHOAREYOU.
t.log.Trace("<< "+p.Name(), "id", c.node.ID(), "addr", fromAddr)
c.handshakeCount++ c.handshakeCount++
c.challenge = p c.challenge = p
p.Node = c.node p.Node = c.node