rpc: log remote address only if available

rpc/client.go

@@ -551,13 +551,13 @@ func (c *Client) dispatch(codec ServerCodec) {
 			}
 
 		case err := <-c.readErr:
-			log.Debug("RPC connection read error", "err", err)
+			conn.handler.log.Debug("RPC connection read error", "err", err)
 			conn.close(err, lastOp)
 			reading = false
 
 		// Reconnect:
 		case newcodec := <-c.reconnected:
-			log.Debug("RPC client reconnected", "reading", reading, "remote", newcodec.RemoteAddr())
+			log.Debug("RPC client reconnected", "reading", reading, "conn", newcodec.RemoteAddr())
 			go c.read(newcodec)
 			if reading {
 				// Wait for the previous read loop to exit. This is a rare case which

rpc/handler.go

@@ -59,6 +59,7 @@ type handler struct {
 	rootCtx        context.Context                // canceled by close()
 	cancelRoot     func()                         // cancel function for rootCtx
 	conn           jsonWriter                     // where responses will be sent
+	log            log.Logger
 	allowSubscribe bool
 
 	subLock    sync.Mutex
@@ -82,6 +83,10 @@ func newHandler(connCtx context.Context, conn jsonWriter, idgen func() ID, reg *
 		cancelRoot:     cancelRoot,
 		allowSubscribe: true,
 		serverSubs:     make(map[ID]*Subscription),
+		log:            log.Root(),
+	}
+	if conn.RemoteAddr() != "" {
+		h.log = h.log.New("conn", conn.RemoteAddr())
 	}
 	h.unsubscribeCb = newCallback(reflect.Value{}, reflect.ValueOf(h.unsubscribe))
 	return h
@@ -235,7 +240,7 @@ func (h *handler) handleImmediate(msg *jsonrpcMessage) bool {
 		return false
 	case msg.isResponse():
 		h.handleResponse(msg)
-		log.Trace("Handled RPC response", "reqid", idForLog{msg.ID}, "conn", h.conn.RemoteAddr(), "t", time.Since(start))
+		h.log.Trace("Handled RPC response", "reqid", idForLog{msg.ID}, "t", time.Since(start))
 		return true
 	default:
 		return false
@@ -246,7 +251,7 @@ func (h *handler) handleImmediate(msg *jsonrpcMessage) bool {
 func (h *handler) handleSubscriptionResult(msg *jsonrpcMessage) {
 	var result subscriptionResult
 	if err := json.Unmarshal(msg.Params, &result); err != nil {
-		log.Debug("Dropping invalid subscription message", "conn", h.conn.RemoteAddr())
+		h.log.Debug("Dropping invalid subscription message")
 		return
 	}
 	if h.clientSubs[result.ID] != nil {
@@ -258,7 +263,7 @@ func (h *handler) handleSubscriptionResult(msg *jsonrpcMessage) {
 func (h *handler) handleResponse(msg *jsonrpcMessage) {
 	op := h.respWait[string(msg.ID)]
 	if op == nil {
-		log.Debug("Unsolicited RPC response", "reqid", idForLog{msg.ID}, "conn", h.conn.RemoteAddr())
+		h.log.Debug("Unsolicited RPC response", "reqid", idForLog{msg.ID})
 		return
 	}
 	delete(h.respWait, string(msg.ID))
@@ -287,11 +292,15 @@ func (h *handler) handleCallMsg(ctx *callProc, msg *jsonrpcMessage) *jsonrpcMess
 	switch {
 	case msg.isNotification():
 		h.handleCall(ctx, msg)
-		log.Debug("Served "+msg.Method, "conn", h.conn.RemoteAddr(), "t", time.Since(start))
+		h.log.Debug("Served "+msg.Method, "t", time.Since(start))
 		return nil
 	case msg.isCall():
 		resp := h.handleCall(ctx, msg)
-		log.Debug("Served "+msg.Method, "reqid", idForLog{msg.ID}, "conn", h.conn.RemoteAddr(), "t", time.Since(start))
+		if resp.Error != nil {
+			h.log.Info("Served "+msg.Method, "reqid", idForLog{msg.ID}, "t", time.Since(start), "err", resp.Error.Message)
+		} else {
+			h.log.Debug("Served "+msg.Method, "reqid", idForLog{msg.ID}, "t", time.Since(start))
+		}
 		return resp
 	case msg.hasValidID():
 		return msg.errorResponse(&invalidRequestError{"invalid request"})

rpc/ipc.go

@@ -34,7 +34,7 @@ func (s *Server) ServeListener(l net.Listener) error {
 		} else if err != nil {
 			return err
 		}
-		log.Trace("Accepted RPC connection", "addr", conn.RemoteAddr())
+		log.Trace("Accepted RPC connection", "conn", conn.RemoteAddr())
 		go s.ServeCodec(NewJSONCodec(conn), OptionMethodInvocation|OptionSubscriptions)
 	}
 }

rpc/json.go

@@ -23,7 +23,6 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"net"
 	"reflect"
 	"strings"
 	"sync"
@@ -142,6 +141,13 @@ type Conn interface {
 	SetWriteDeadline(time.Time) error
 }
 
+// ConnRemoteAddr wraps the RemoteAddr operation, which returns a description
+// of the peer address of a connection. If a Conn also implements ConnRemoteAddr, this
+// description is used in log messages.
+type ConnRemoteAddr interface {
+	RemoteAddr() string
+}
+
 // connWithRemoteAddr overrides the remote address of a connection.
 type connWithRemoteAddr struct {
 	Conn
@@ -166,20 +172,13 @@ type jsonCodec struct {
 // on explicitly given encoding and decoding methods.
 func NewCodec(conn Conn, encode, decode func(v interface{}) error) ServerCodec {
 	codec := &jsonCodec{
-		remoteAddr: "unknown",
-		closed:     make(chan interface{}),
-		encode:     encode,
-		decode:     decode,
-		conn:       conn,
+		closed: make(chan interface{}),
+		encode: encode,
+		decode: decode,
+		conn:   conn,
 	}
-
-	// Try to figure out the remote address.
-	type remoteStringAddr interface{ RemoteAddr() string }
-	type remoteNetAddr interface{ RemoteAddr() net.Addr }
-	if ra, ok := conn.(remoteStringAddr); ok {
+	if ra, ok := conn.(ConnRemoteAddr); ok {
 		codec.remoteAddr = ra.RemoteAddr()
-	} else if ra, ok := conn.(remoteNetAddr); ok {
-		codec.remoteAddr = ra.RemoteAddr().String()
 	}
 	return codec
 }