diff --git a/rpc/client.go b/rpc/client.go index 36724d8379..6ca5b3c6cc 100644 --- a/rpc/client.go +++ b/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 diff --git a/rpc/handler.go b/rpc/handler.go index 43a35c5b99..bc03ef25f4 100644 --- a/rpc/handler.go +++ b/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"}) diff --git a/rpc/ipc.go b/rpc/ipc.go index c6f4ec2176..ad8ce03098 100644 --- a/rpc/ipc.go +++ b/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) } } diff --git a/rpc/json.go b/rpc/json.go index dc863ccb78..b2e8c7bab3 100644 --- a/rpc/json.go +++ b/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 }