switch to structured logging

libp2p · Aug 19, 2020 · 216e2b8 · 216e2b8
1 parent 221abff
commit 216e2b8
Show file tree

Hide file tree

Showing 12 changed files with 56 additions and 47 deletions.
diff --git a/bootstrap.go b/bootstrap.go
@@ -72,7 +72,7 @@ func (d *Daemon) connectBootstrapPeers(pis []*pstore.PeerInfo, toconnect int) in
 		}
 		err := d.host.Connect(ctx, *pi)
 		if err != nil {
-			log.Debugf("Error connecting to bootstrap peer %s: %s", pi.ID, err.Error())
+			log.Debugw("Error connecting to bootstrap peer", "peer", pi.ID, "error", err)
 		} else {
 			d.host.ConnManager().TagPeer(pi.ID, "bootstrap", 1)
 			count++

diff --git a/conn.go b/conn.go
@@ -30,35 +30,35 @@ func (d *Daemon) handleConn(c net.Conn) {
 		err := r.ReadMsg(&req)
 		if err != nil {
 			if err != io.EOF {
-				log.Debugf("Error reading message: %s", err.Error())
+				log.Debugw("error reading message", "error", err)
 			}
 			return
 		}
 
-		log.Debugf("request: %d [%s]", *req.Type, req.Type.String())
+		log.Debugw("request", "type", req.GetType())
 
-		switch *req.Type {
+		switch req.GetType() {
 		case pb.Request_IDENTIFY:
 			res := d.doIdentify(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_CONNECT:
 			res := d.doConnect(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_STREAM_OPEN:
 			res, s := d.doStreamOpen(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				if s != nil {
 					s.Reset()
 				}
@@ -74,15 +74,15 @@ func (d *Daemon) handleConn(c net.Conn) {
 			res := d.doStreamHandler(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_DHT:
 			res, ch, cancel := d.doDHT(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				if ch != nil {
 					cancel()
 				}
@@ -93,15 +93,15 @@ func (d *Daemon) handleConn(c net.Conn) {
 				for res := range ch {
 					err = w.WriteMsg(res)
 					if err != nil {
-						log.Debugf("Error writing response: %s", err.Error())
+						log.Debugw("error writing response", "error", err)
 						cancel()
 						return
 					}
 				}
 
 				err = w.WriteMsg(dhtResponseEnd())
 				if err != nil {
-					log.Debugf("Error writing response: %s", err.Error())
+					log.Debugw("error writing response", "error", err)
 					return
 				}
 			}
@@ -110,31 +110,31 @@ func (d *Daemon) handleConn(c net.Conn) {
 			res := d.doListPeers(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_CONNMANAGER:
 			res := d.doConnManager(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_DISCONNECT:
 			res := d.doDisconnect(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				return
 			}
 
 		case pb.Request_PUBSUB:
 			res, sub := d.doPubsub(&req)
 			err := w.WriteMsg(res)
 			if err != nil {
-				log.Debugf("Error writing response: %s", err.Error())
+				log.Debugw("error writing response", "error", err)
 				if sub != nil {
 					sub.Cancel()
 				}
@@ -147,7 +147,7 @@ func (d *Daemon) handleConn(c net.Conn) {
 			}
 
 		default:
-			log.Debugf("Unexpected request type: %d", *req.Type)
+			log.Debugw("unexpected request type", "type", req.GetType())
 			return
 		}
 	}
@@ -176,7 +176,7 @@ func (d *Daemon) doConnect(req *pb.Request) *pb.Response {
 
 	pid, err := peer.IDFromBytes(req.Connect.Peer)
 	if err != nil {
-		log.Debugf("Error parsing peer ID: %s", err.Error())
+		log.Debugw("error parsing peer ID", "error", err)
 		return errorResponse(err)
 	}
 
@@ -185,18 +185,18 @@ func (d *Daemon) doConnect(req *pb.Request) *pb.Response {
 	for x, bs := range req.Connect.Addrs {
 		addr, err := ma.NewMultiaddrBytes(bs)
 		if err != nil {
-			log.Debugf("Error parsing multiaddr: %s", err.Error())
+			log.Debugw("Error parsing multiaddr", "error", err)
 			return errorResponse(err)
 		}
 		addrs[x] = addr
 	}
 
 	pi := peer.AddrInfo{ID: pid, Addrs: addrs}
 
-	log.Debugf("connecting to %s", pid.Pretty())
+	log.Debug("connecting", "to", pid)
 	err = d.host.Connect(ctx, pi)
 	if err != nil {
-		log.Debugf("error opening connection to %s: %s", pid.Pretty(), err.Error())
+		log.Debugw("error opening connection", "to", pid, "error", err)
 		return errorResponse(err)
 	}
 
@@ -231,7 +231,7 @@ func (d *Daemon) doStreamOpen(req *pb.Request) (*pb.Response, network.Stream) {
 
 	pid, err := peer.IDFromBytes(req.StreamOpen.Peer)
 	if err != nil {
-		log.Debugf("Error parsing peer ID: %s", err.Error())
+		log.Debugw("Error parsing peer ID", "error", err)
 		return errorResponse(err), nil
 	}
 
@@ -240,10 +240,10 @@ func (d *Daemon) doStreamOpen(req *pb.Request) (*pb.Response, network.Stream) {
 		protos[x] = protocol.ID(str)
 	}
 
-	log.Debugf("opening stream to %s", pid.Pretty())
+	log.Debugf("opening stream", "to", pid)
 	s, err := d.host.NewStream(ctx, pid, protos...)
 	if err != nil {
-		log.Debugf("Error opening stream to %s: %s", pid.Pretty(), err.Error())
+		log.Debugw("error opening stream", "to", pid, "error", err)
 		return errorResponse(err), nil
 	}
 
@@ -270,7 +270,7 @@ func (d *Daemon) doStreamHandler(req *pb.Request) *pb.Response {
 		if !ok {
 			d.host.SetStreamHandler(p, d.handleStream)
 		}
-		log.Debugf("set stream handler: %s -> %s", sp, maddr.String())
+		log.Debugw("set stream handler", "protocol", sp, "to", maddr)
 		d.handlers[p] = maddr
 	}
 

diff --git a/connmgr.go b/connmgr.go
@@ -14,7 +14,7 @@ func (d *Daemon) doConnManager(req *pb.Request) *pb.Response {
 		return errorResponseString("Malformed request; missing parameters")
 	}
 
-	switch *req.ConnManager.Type {
+	switch req.ConnManager.GetType() {
 	case pb.ConnManagerRequest_TAG_PEER:
 		p, err := peer.IDFromBytes(req.ConnManager.GetPeer())
 		if err != nil {
@@ -52,7 +52,7 @@ func (d *Daemon) doConnManager(req *pb.Request) *pb.Response {
 		return okResponse()
 
 	default:
-		log.Debugf("Unexpected ConnManager request type: %d", *req.ConnManager.Type)
+		log.Debugf("unexpected ConnManager request type", "type", req.ConnManager.GetType())
 		return errorResponseString("Unexpected request")
 	}
 }
diff --git a/daemon.go b/daemon.go
@@ -140,7 +140,7 @@ func (d *Daemon) listen() {
 
 		c, err := d.listener.Accept()
 		if err != nil {
-			log.Errorf("error accepting connection: %s", err.Error())
+			log.Errorw("error accepting connection", "error", err)
 			continue
 		}
 

diff --git a/dht.go b/dht.go
@@ -22,7 +22,7 @@ func (d *Daemon) doDHT(req *pb.Request) (*pb.Response, <-chan *pb.DHTResponse, f
 		return errorResponseString("Malformed request; missing parameters"), nil, nil
 	}
 
-	switch *req.Dht.Type {
+	switch req.Dht.GetType() {
 	case pb.DHTRequest_FIND_PEER:
 		return d.doDHTFindPeer(req.Dht)
 
@@ -51,7 +51,7 @@ func (d *Daemon) doDHT(req *pb.Request) (*pb.Response, <-chan *pb.DHTResponse, f
 		return d.doDHTProvide(req.Dht)
 
 	default:
-		log.Debugf("Unexpected DHT request type: %d", *req.Dht.Type)
+		log.Debugw("unexpected DHT request type", "type", req.Dht.GetType())
 		return errorResponseString("Unexpected request"), nil, nil
 	}
 }

diff --git a/go.sum b/go.sum
@@ -214,6 +214,7 @@ github.com/ipfs/go-log v0.0.2-0.20190920042044-a609c1ae5144/go.mod h1:azGN5dH7ai
 github.com/ipfs/go-todocounter v0.0.1 h1:kITWA5ZcQZfrUnDNkRn04Xzh0YFaDFXsoO2A81Eb6Lw=
 github.com/ipfs/go-todocounter v0.0.1/go.mod h1:l5aErvQc8qKE2r7NDMjmq5UNAvuZy0rC8BHOplkWvZ4=
 github.com/jackpal/gateway v1.0.5 h1:qzXWUJfuMdlLMtt0a3Dgt+xkWQiA5itDEITVJtuSwMc=
+github.com/jackpal/gateway v1.0.5 h1:qzXWUJfuMdlLMtt0a3Dgt+xkWQiA5itDEITVJtuSwMc=
 github.com/jackpal/gateway v1.0.5/go.mod h1:lTpwd4ACLXmpyiCTRtfiNyVnUmqT9RivzCDQetPfnjA=
 github.com/jackpal/go-nat-pmp v1.0.1/go.mod h1:QPH045xvCAeXUZOxsnwmrtiCoxIr9eob+4orBN1SBKc=
 github.com/jackpal/go-nat-pmp v1.0.2 h1:KzKSgb7qkJvOUTqYl9/Hg/me3pWgBmERKrTGD7BdWus=
@@ -577,6 +578,8 @@ github.com/onsi/gomega v1.9.0 h1:R1uwffexN6Pr340GtYRIdZmAiN4J+iw6WG4wog1DUXg=
 github.com/onsi/gomega v1.9.0/go.mod h1:Ho0h+IUsWyvy1OpqCwxlQ/21gkhVunqlU8fDGcoTdcA=
 github.com/opentracing/opentracing-go v1.0.2/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o=
 github.com/opentracing/opentracing-go v1.1.0 h1:pWlfV3Bxv7k65HYwkikxat0+s3pV4bsqf19k25Ur8rU=
+github.com/opentracing/opentracing-go v1.1.0 h1:pWlfV3Bxv7k65HYwkikxat0+s3pV4bsqf19k25Ur8rU=
+github.com/opentracing/opentracing-go v1.1.0/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o=
 github.com/opentracing/opentracing-go v1.1.0/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o=
 github.com/opentracing/opentracing-go v1.2.0 h1:uEJPy/1a5RIPAJ0Ov+OIO8OxWu77jEv+1B0VhjKrZUs=
 github.com/opentracing/opentracing-go v1.2.0/go.mod h1:GxEUsuufX4nBwe+T+Wl9TAgYrxe9dPLANfrWvHYVTgc=
@@ -690,16 +693,22 @@ go.opencensus.io v0.22.3 h1:8sGtKOrtQqkN1bp2AtX+misvLIlOmsEsNd+9NIcPEm8=
 go.opencensus.io v0.22.3/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
 go.opencensus.io v0.22.4 h1:LYy1Hy3MJdrCdMwwzxA/dRok4ejH+RwNGbuoD9fCjto=
 go.opencensus.io v0.22.4/go.mod h1:yxeiOL68Rb0Xd1ddK5vPZ/oVn4vY4Ynel7k9FzqtOIw=
+go.uber.org/atomic v1.4.0 h1:cxzIVoETapQEqDhQu3QfnvXAV4AlzcvUCxkVUFw3+EU=
+go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
 go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
 go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk=
 go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
 go.uber.org/goleak v1.0.0 h1:qsup4IcBdlmsnGfqyLl4Ntn3C2XCCuKAE7DwHpScyUo=
 go.uber.org/goleak v1.0.0/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
+go.uber.org/multierr v1.1.0 h1:HoEmRHQPVSqub6w2z2d2EOVs2fjyFRGyofhKuyDq0QI=
+go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
 go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
 go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A=
 go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
 go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4=
 go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
+go.uber.org/zap v1.10.0 h1:ORx85nbTijNz8ljznvCMR1ZBIPKFn3jQrag10X2AsuM=
+go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 go.uber.org/zap v1.14.1/go.mod h1:Mb2vm2krFEG5DV0W9qcHBYFtp/Wku1cvYaqPsS/WYfc=
 go.uber.org/zap v1.15.0 h1:ZZCA22JRF2gQE5FoNmhmrf7jeJJ2uhqDUNRYKm8dvmM=

diff --git a/p2pclient/dht.go b/p2pclient/dht.go
@@ -37,7 +37,7 @@ func convertPbPeerInfo(pbi *pb.PeerInfo) (PeerInfo, error) {
 	for _, addrbytes := range pbi.Addrs {
 		addr, err := ma.NewMultiaddrBytes(addrbytes)
 		if err != nil {
-			log.Errorf("error parsing multiaddr in peerinfo: %s", err)
+			log.Errorw("error parsing multiaddr in peerinfo", "error", err)
 			continue
 		}
 		addrs = append(addrs, addr)
@@ -83,7 +83,7 @@ func readDhtResponseStream(ctx context.Context, control net.Conn) (<-chan *pb.DH
 			default:
 				msg := &pb.DHTResponse{}
 				if err := r.ReadMsg(msg); err != nil {
-					log.Errorf("reading daemon response: %s", err)
+					log.Errorw("reading daemon response", "error", err)
 					return
 				}
 
@@ -226,7 +226,7 @@ func convertResponseToPeerInfo(respc <-chan *pb.DHTResponse) <-chan PeerInfo {
 		for resp := range respc {
 			info, err := convertPbPeerInfo(resp.GetPeer())
 			if err != nil {
-				log.Errorf("error converting peerinfo: %s", err.Error())
+				log.Errorw("error converting peerinfo", "error", err)
 				continue
 			}
 
@@ -246,7 +246,7 @@ func convertResponseToPeerID(respc <-chan *pb.DHTResponse) <-chan peer.ID {
 		for resp := range respc {
 			id, err := peer.IDFromBytes(resp.GetValue())
 			if err != nil {
-				log.Errorf("error parsing peer id: %s", err.Error())
+				log.Errorw("error parsing peer id", "error", err)
 				continue
 			}
 

diff --git a/p2pclient/pubsub.go b/p2pclient/pubsub.go
@@ -85,7 +85,7 @@ func (c *Client) streamPubsubRequest(ctx context.Context, psReq *pb.PSRequest) (
 		for {
 			msg := &pb.PSMessage{}
 			if err := r.ReadMsg(msg); err != nil {
-				log.Errorf("reading pubsub message: %s", err)
+				log.Errorw("reading pubsub message", "error", err)
 				return
 			}
 			out <- msg

diff --git a/p2pclient/streams.go b/p2pclient/streams.go
@@ -136,21 +136,21 @@ func (c *Client) streamDispatcher() {
 	for {
 		rawconn, err := c.listener.Accept()
 		if err != nil {
-			log.Warningf("accepting incoming connection: %s", err)
+			log.Warnw("accepting incoming connection", "error", err)
 			return
 		}
 		conn := &byteReaderConn{rawconn}
 
 		info := &pb.StreamInfo{}
 		err = readMsgSafe(conn, info)
 		if err != nil {
-			log.Errorf("error reading stream info: %s", err)
+			log.Errorw("error reading stream info", "error", err)
 			conn.Close()
 			continue
 		}
 		streamInfo, err := convertStreamInfo(info)
 		if err != nil {
-			log.Errorf("error parsing stream info: %s", err)
+			log.Errorw("error parsing stream info", "error", err)
 			conn.Close()
 			continue
 		}

diff --git a/pubsub.go b/pubsub.go
@@ -18,7 +18,7 @@ func (d *Daemon) doPubsub(req *pb.Request) (*pb.Response, *ps.Subscription) {
 		return errorResponseString("Malformed request; missing parameters"), nil
 	}
 
-	switch *req.Pubsub.Type {
+	switch req.Pubsub.GetType() {
 	case pb.PSRequest_GET_TOPICS:
 		return d.doPubsubGetTopics(req.Pubsub)
 
@@ -32,7 +32,7 @@ func (d *Daemon) doPubsub(req *pb.Request) (*pb.Response, *ps.Subscription) {
 		return d.doPubsubSubscribe(req.Pubsub)
 
 	default:
-		log.Debugf("Unexpected pubsub request type: %d", *req.Pubsub.Type)
+		log.Debugw("unexpected pubsub request type", "type", req.Pubsub.GetType())
 		return errorResponseString("Unexpected request"), nil
 	}
 }
@@ -89,22 +89,22 @@ func (d *Daemon) doPubsubPipe(sub *ps.Subscription, r ggio.ReadCloser, w ggio.Wr
 				return
 			}
 
-			log.Warnf("unexpected message (%s)", req.GetType().String())
+			log.Warnw("unexpected message", "type", req.GetType())
 		}
 	}()
 
 	for {
 		msg, err := sub.Next(d.ctx)
 		if err != nil {
-			log.Warnf("subscription error: %s", err.Error())
+			log.Warnw("subscription error", "error", err)
 			// goroutine will cancel the subscription once the connection is closed on return
 			return
 		}
 
 		psmsg := psMessage(msg)
 		err = w.WriteMsg(psmsg)
 		if err != nil {
-			log.Warnf("error writing pubsub message: %s", err.Error())
+			log.Warnw("error writing pubsub message", "error", err)
 			// goroutine will cancel the subscription once the connection is closed on return
 			return
 		}