adapt log messages for new logger interface

Author: joao-r-reis

cluster.go

@@ -344,7 +344,7 @@ func (cfg *ClusterConfig) translateAddressPort(addr net.IP, port int, logger Str
 		return addr, port
 	}
 	newAddr, newPort := cfg.AddressTranslator.Translate(addr, port)
-	logger.Debug("translating address '%v:%d' to '%v:%d'",
+	logger.Debug("Translating address.",
 		newLogFieldIp("old_addr", addr), newLogFieldInt("old_port", port),
 		newLogFieldIp("new_addr", newAddr), newLogFieldInt("new_port", newPort))
 	return newAddr, newPort

conn.go

@@ -700,7 +700,7 @@ func (c *Conn) processFrame(ctx context.Context, r io.Reader) error {
 	delete(c.calls, head.stream)
 	c.mu.Unlock()
 	if call == nil || !ok {
-		c.logger.Warning("received response for stream which has no handler: header=%v", newLogFieldString("header", head.String()))
+		c.logger.Warning("Received response for stream which has no handler.", newLogFieldString("header", head.String()))
 		return c.discardFrame(r, head)
 	} else if head.stream != call.streamID {
 		panic(fmt.Sprintf("call has incorrect streamID: got %d expected %d", call.streamID, head.stream))
@@ -1315,18 +1315,18 @@ func (c *Conn) execInternal(ctx context.Context, req frameBuilder, tracer Tracer
 		return resp.framer, nil
 	case <-timeoutCh:
 		close(call.timeout)
-		c.logger.Debug("Request timed out on connection %v (%v)",
+		c.logger.Debug("Request timed out on connection.",
 			newLogFieldString("host_id", c.host.HostID()), newLogFieldIp("addr", c.host.ConnectAddress()))
 		c.handleTimeout()
 		return nil, ErrTimeoutNoResponse
 	case <-ctxDone:
-		c.logger.Debug("Request failed because context elapsed out on connection %v (%v): %v",
+		c.logger.Debug("Request failed because context elapsed out on connection.",
 			newLogFieldString("host_id", c.host.HostID()), newLogFieldIp("addr", c.host.ConnectAddress()),
 			newLogFieldError("ctx_err", ctx.Err()))
 		close(call.timeout)
 		return nil, ctx.Err()
 	case <-c.ctx.Done():
-		c.logger.Debug("Request failed because connection closed %v (%v).",
+		c.logger.Debug("Request failed because connection closed.",
 			newLogFieldString("host_id", c.host.HostID()), newLogFieldIp("addr", c.host.ConnectAddress()))
 		close(call.timeout)
 		return nil, ErrConnectionClosed
@@ -1668,7 +1668,7 @@ func (c *Conn) executeQuery(ctx context.Context, qry *Query) *Iter {
 		iter := &Iter{framer: framer}
 		if err := c.awaitSchemaAgreement(ctx); err != nil {
 			// TODO: should have this behind a flag
-			c.logger.Warning("error while awaiting for schema agreement after a schema change event: %v", newLogFieldError("err", err))
+			c.logger.Warning("Error while awaiting for schema agreement after a schema change event.", newLogFieldError("err", err))
 		}
 		// dont return an error from this, might be a good idea to give a warning
 		// though. The impact of this returning an error would be that the cluster
@@ -1920,7 +1920,7 @@ func (c *Conn) awaitSchemaAgreement(ctx context.Context) (err error) {
 				goto cont
 			}
 			if !isValidPeer(host) || host.schemaVersion == "" {
-				c.logger.Warning("invalid peer or peer with empty schema_version: peer=%s", newLogFieldIp("peer", host.ConnectAddress()))
+				c.logger.Warning("Invalid peer or peer with empty schema_version.", newLogFieldIp("peer", host.ConnectAddress()))
 				continue
 			}
 

conn_test.go

@@ -206,7 +206,7 @@ func TestDNSLookupConnected(t *testing.T) {
 		t.Fatal("CreateSession() should have connected")
 	}
 
-	if !strings.Contains(log.String(), "gocql: dns error") {
+	if !strings.Contains(log.String(), "gocql: DNS error") {
 		t.Fatalf("Expected to receive dns error log message  - got '%s' instead", log.String())
 	}
 }
@@ -230,7 +230,7 @@ func TestDNSLookupError(t *testing.T) {
 		t.Fatal("CreateSession() should have returned an error")
 	}
 
-	if !strings.Contains(log.String(), "gocql: dns error") {
+	if !strings.Contains(log.String(), "gocql: DNS error") {
 		t.Fatalf("Expected to receive dns error log message  - got '%s' instead", log.String())
 	}
 
@@ -357,7 +357,7 @@ func (o *testQueryObserver) ObserveQuery(ctx context.Context, q ObservedQuery) {
 	host := q.Host.ConnectAddress().String()
 	o.metrics[host] = q.Metrics
 	if o.verbose {
-		o.logger.Debug("Observed query %q. Returned %v rows, took %v on host %q with %v attempts and total latency %v. Error: %q\n",
+		o.logger.Debug("Observed query.",
 			newLogFieldString("stmt", q.Statement),
 			newLogFieldInt("rows", q.Rows),
 			newLogFieldString("duration", q.End.Sub(q.Start).String()),

connectionpool.go

@@ -493,19 +493,19 @@ func (pool *hostConnPool) logConnectErr(err error) {
 	if opErr, ok := err.(*net.OpError); ok && (opErr.Op == "dial" || opErr.Op == "read") {
 		// connection refused
 		// these are typical during a node outage so avoid log spam.
-		pool.logger.Debug("unable to dial %s (%s): %v",
+		pool.logger.Debug("Pool unable to establish a connection to host.",
 			newLogFieldIp("host_addr", pool.host.ConnectAddress()), newLogFieldString("host_id", pool.host.HostID()), newLogFieldError("err", err))
 	} else if err != nil {
 		// unexpected error
-		pool.logger.Debug("failed to connect to %s (%s) due to error: %v",
+		pool.logger.Debug("Pool failed to connect to host due to error.",
 			newLogFieldIp("host_addr", pool.host.ConnectAddress()), newLogFieldString("host_id", pool.host.HostID()), newLogFieldError("err", err))
 	}
 }
 
 // transition back to a not-filling state.
 func (pool *hostConnPool) fillingStopped(err error) {
 	if err != nil {
-		pool.logger.Warning("connection pool filling failed %s (%s): %v",
+		pool.logger.Warning("Connection pool filling failed.",
 			newLogFieldIp("host_addr", pool.host.ConnectAddress()), newLogFieldString("host_id", pool.host.HostID()), newLogFieldError("err", err))
 		// wait for some time to avoid back-to-back filling
 		// this provides some time between failed attempts
@@ -522,7 +522,7 @@ func (pool *hostConnPool) fillingStopped(err error) {
 
 	// if we errored and the size is now zero, make sure the host is marked as down
 	// see https://github.com/apache/cassandra-gocql-driver/issues/1614
-	pool.logger.Debug("conns of pool after stopped %s (%s): %v",
+	pool.logger.Debug("Logging number of connections of pool after filling stopped.",
 		newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()), newLogFieldInt("count", count))
 	if err != nil && count == 0 {
 		if pool.session.cfg.ConvictionPolicy.AddFailure(err, host) {
@@ -579,7 +579,7 @@ func (pool *hostConnPool) connect() (err error) {
 				break
 			}
 		}
-		pool.logger.Warning("connection failed %s (%s): %v, reconnecting with %v",
+		pool.logger.Warning("Pool failed to connect to host. Reconnecting according to the reconnection policy.",
 			newLogFieldIp("host", pool.host.ConnectAddress()),
 			newLogFieldString("host_id", pool.host.HostID()),
 			newLogFieldError("err", err),
@@ -630,7 +630,7 @@ func (pool *hostConnPool) HandleError(conn *Conn, err error, closed bool) {
 		return
 	}
 
-	pool.logger.Info("pool connection error %v: %v",
+	pool.logger.Info("Pool connection error.",
 		newLogFieldString("addr", conn.addr), newLogFieldError("err", err))
 
 	// find the connection index

control.go

@@ -105,7 +105,7 @@ func (c *controlConn) heartBeat() {
 
 		resp, err := c.writeFrame(&writeOptionsFrame{})
 		if err != nil {
-			c.session.logger.Debug("control connection heartbeat failed: %v.", newLogFieldError("err", err))
+			c.session.logger.Debug("Control connection failed to send heartbeat.", newLogFieldError("err", err))
 			goto reconn
 		}
 
@@ -115,10 +115,10 @@ func (c *controlConn) heartBeat() {
 			sleepTime = 5 * time.Second
 			continue
 		case error:
-			c.session.logger.Debug("control connection heartbeat failed: %v.", newLogFieldError("err", actualResp))
+			c.session.logger.Debug("Control connection heartbeat failed.", newLogFieldError("err", actualResp))
 			goto reconn
 		default:
-			c.session.logger.Error("unknown frame in response to options: %v", newLogFieldString("frame_type", fmt.Sprintf("%T", resp)))
+			c.session.logger.Error("Unknown frame in response to options.", newLogFieldString("frame_type", fmt.Sprintf("%T", resp)))
 		}
 
 	reconn:
@@ -246,18 +246,18 @@ func (c *controlConn) discoverProtocol(hosts []*HostInfo) (int, error) {
 		}
 
 		if err == nil {
-			c.session.logger.Debug("discovered protocol version %v using host %v (%s).",
+			c.session.logger.Debug("Discovered protocol version using host.",
 				newLogFieldInt("protocol_version", connCfg.ProtoVersion), newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()))
 			return connCfg.ProtoVersion, nil
 		}
 
 		if proto := parseProtocolFromError(err); proto > 0 {
-			c.session.logger.Debug("discovered protocol version %v using host %v (%s).",
+			c.session.logger.Debug("Discovered protocol version using host after parsing protocol error.",
 				newLogFieldInt("protocol_version", proto), newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()))
 			return proto, nil
 		}
 
-		c.session.logger.Debug("failed to discover protocol version using host %v (%v): %v.",
+		c.session.logger.Debug("Failed to discover protocol version using host.",
 			newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()), newLogFieldError("err", err))
 	}
 
@@ -281,7 +281,7 @@ func (c *controlConn) connect(hosts []*HostInfo) error {
 	for _, host := range hosts {
 		conn, err = c.session.dial(c.session.ctx, host, &cfg, c)
 		if err != nil {
-			c.session.logger.Info("unable to dial control conn %s:%v (%s): %v",
+			c.session.logger.Info("Control connection failed to establish a connection to host.",
 				newLogFieldIp("host_addr", host.ConnectAddress()),
 				newLogFieldInt("port", host.Port()),
 				newLogFieldString("host_id", host.HostID()),
@@ -292,7 +292,7 @@ func (c *controlConn) connect(hosts []*HostInfo) error {
 		if err == nil {
 			break
 		}
-		c.session.logger.Info("unable setup control conn %v:%v (%s): %v",
+		c.session.logger.Info("Control connection setup failed after connecting to host.",
 			newLogFieldIp("host_addr", host.ConnectAddress()),
 			newLogFieldInt("port", host.Port()),
 			newLogFieldString("host_id", host.HostID()),
@@ -333,7 +333,7 @@ func (c *controlConn) setupConn(conn *Conn) error {
 	}
 
 	if !exists {
-		c.session.logger.Info("adding host %v (%v).",
+		c.session.logger.Info("Adding host.",
 			newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()))
 	}
 
@@ -348,7 +348,7 @@ func (c *controlConn) setupConn(conn *Conn) error {
 
 	c.conn.Store(ch)
 
-	c.session.logger.Info("control connection connected to %v (%s).",
+	c.session.logger.Info("Control connection connected to host.",
 		newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldString("host_id", host.HostID()))
 
 	if c.session.initialized() {
@@ -410,21 +410,21 @@ func (c *controlConn) reconnect() {
 	_, err := c.attemptReconnect()
 
 	if err != nil {
-		c.session.logger.Error("unable to reconnect control connection: %v",
+		c.session.logger.Error("Unable to reconnect control connection.",
 			newLogFieldError("err", err))
 		return
 	}
 
 	err = c.session.refreshRing()
 	if err != nil {
-		c.session.logger.Warning("unable to refresh ring: %v",
+		c.session.logger.Warning("Unable to refresh ring.",
 			newLogFieldError("err", err))
 	}
 }
 
 func (c *controlConn) attemptReconnect() (*Conn, error) {
 
-	c.session.logger.Info("reconnecting the control connection.")
+	c.session.logger.Info("Reconnecting the control connection.")
 
 	hosts := c.session.ring.allHosts()
 	hosts = shuffleHosts(hosts)
@@ -448,7 +448,7 @@ func (c *controlConn) attemptReconnect() (*Conn, error) {
 		return conn, err
 	}
 
-	c.session.logger.Error("unable to connect to any ring node, control connection falling back to initial contact points: %v", newLogFieldError("err", err))
+	c.session.logger.Error("Unable to connect to any ring node, control connection falling back to initial contact points.", newLogFieldError("err", err))
 	// Fallback to initial contact points, as it may be the case that all known initialHosts
 	// changed their IPs while keeping the same hostname(s).
 	initialHosts, resolvErr := addrsToHosts(c.session.cfg.Hosts, c.session.cfg.Port, c.session.logger)
@@ -465,7 +465,7 @@ func (c *controlConn) attemptReconnectToAnyOfHosts(hosts []*HostInfo) (*Conn, er
 	for _, host := range hosts {
 		conn, err = c.session.connect(c.session.ctx, host, c)
 		if err != nil {
-			c.session.logger.Info("unable to dial control conn %s:%v (%s): %v",
+			c.session.logger.Info("During reconnection, control connection failed to establish a connection to host.",
 				newLogFieldIp("host_addr", host.ConnectAddress()),
 				newLogFieldInt("port", host.Port()),
 				newLogFieldString("host_id", host.HostID()),
@@ -476,7 +476,7 @@ func (c *controlConn) attemptReconnectToAnyOfHosts(hosts []*HostInfo) (*Conn, er
 		if err == nil {
 			break
 		}
-		c.session.logger.Info("unable setup control conn %v:%v (%s): %v",
+		c.session.logger.Info("During reconnection, control connection setup failed after connecting to host.",
 			newLogFieldIp("host_addr", host.ConnectAddress()),
 			newLogFieldInt("port", host.Port()),
 			newLogFieldString("host_id", host.HostID()),
@@ -500,7 +500,7 @@ func (c *controlConn) HandleError(conn *Conn, err error, closed bool) {
 		return
 	}
 
-	c.session.logger.Info("control connection error %v (%s): %v",
+	c.session.logger.Info("Control connection error.",
 		newLogFieldIp("host_addr", conn.host.ConnectAddress()),
 		newLogFieldString("host_id", conn.host.HostID()),
 		newLogFieldError("err", err))
@@ -567,7 +567,7 @@ func (c *controlConn) query(statement string, values ...interface{}) (iter *Iter
 		})
 
 		if iter.err != nil {
-			c.session.logger.Warning("control: error executing %v: %v",
+			c.session.logger.Warning("Error executing control connection statement.",
 				newLogFieldString("statement", statement), newLogFieldError("err", iter.err))
 		}
 

events.go

@@ -103,7 +103,7 @@ func (e *eventDebouncer) debounce(frame frame) {
 	if len(e.events) < eventBufferSize {
 		e.events = append(e.events, frame)
 	} else {
-		e.logger.Warning("%s: buffer full, dropping event frame: %s",
+		e.logger.Warning("Event buffer full, dropping event frame.",
 			newLogFieldString("event_name", e.name), newLogFieldStringer("frame", frame))
 	}
 
@@ -113,11 +113,11 @@ func (e *eventDebouncer) debounce(frame frame) {
 func (s *Session) handleEvent(framer *framer) {
 	frame, err := framer.parseFrame()
 	if err != nil {
-		s.logger.Error("unable to parse event frame: %v", newLogFieldError("err", err))
+		s.logger.Error("Unable to parse event frame.", newLogFieldError("err", err))
 		return
 	}
 
-	s.logger.Debug("handling event frame: %v", newLogFieldStringer("frame", frame))
+	s.logger.Debug("Handling event frame.", newLogFieldStringer("frame", frame))
 
 	switch f := frame.(type) {
 	case *schemaChangeKeyspace, *schemaChangeFunction,
@@ -127,7 +127,7 @@ func (s *Session) handleEvent(framer *framer) {
 	case *topologyChangeEventFrame, *statusChangeEventFrame:
 		s.nodeEvents.debounce(frame)
 	default:
-		s.logger.Error("invalid event frame (%v): %v",
+		s.logger.Error("Invalid event frame.",
 			newLogFieldString("frame_type", fmt.Sprintf("%T", f)), newLogFieldStringer("frame", f))
 	}
 }
@@ -180,7 +180,7 @@ func (s *Session) handleNodeEvent(frames []frame) {
 	for _, frame := range frames {
 		switch f := frame.(type) {
 		case *topologyChangeEventFrame:
-			s.logger.Warning("received topology change event: %v",
+			s.logger.Warning("Received topology change event.",
 				newLogFieldString("frame", strings.Join([]string{f.change, "->", f.host.String(), ":", strconv.Itoa(f.port)}, "")))
 			topologyEventReceived = true
 		case *statusChangeEventFrame:
@@ -198,7 +198,7 @@ func (s *Session) handleNodeEvent(frames []frame) {
 	}
 
 	for _, f := range sEvents {
-		s.logger.Info("dispatching status change event: %v",
+		s.logger.Info("Dispatching status change event.",
 			newLogFieldString("frame", strings.Join([]string{f.change, "->", f.host.String(), ":", strconv.Itoa(f.port)}, "")))
 
 		// ignore events we received if they were disabled
@@ -217,7 +217,7 @@ func (s *Session) handleNodeEvent(frames []frame) {
 }
 
 func (s *Session) handleNodeUp(eventIp net.IP, eventPort int) {
-	s.logger.Info("node is UP: %s:%d",
+	s.logger.Info("Node is UP.",
 		newLogFieldStringer("event_ip", eventIp), newLogFieldInt("event_port", eventPort))
 
 	host, ok := s.ring.getHostByIP(eventIp.String())
@@ -243,7 +243,7 @@ func (s *Session) startPoolFill(host *HostInfo) {
 }
 
 func (s *Session) handleNodeConnected(host *HostInfo) {
-	s.logger.Debug("connected to node: %s:%d (%s)",
+	s.logger.Debug("Pool connected to node.",
 		newLogFieldIp("host_addr", host.ConnectAddress()), newLogFieldInt("port", host.Port()), newLogFieldString("host_id", host.HostID()))
 
 	host.setState(NodeUp)
@@ -254,7 +254,7 @@ func (s *Session) handleNodeConnected(host *HostInfo) {
 }
 
 func (s *Session) handleNodeDown(ip net.IP, port int) {
-	s.logger.Warning("node is DOWN: %s:%d",
+	s.logger.Warning("Node is DOWN.",
 		newLogFieldIp("host_addr", ip), newLogFieldInt("port", port))
 
 	host, ok := s.ring.getHostByIP(ip.String())

helpers.go

@@ -181,7 +181,7 @@ func getCassandraLongType(name string, protoVer byte, logger StructuredLogger) T
 	} else if strings.HasPrefix(name, MAP_TYPE) {
 		names := splitJavaCompositeTypes(name, MAP_TYPE)
 		if len(names) != 2 {
-			logger.Warning("Error parsing map type, it has %d subelements, expecting 2",
+			logger.Warning("Error parsing map type, expected 2 subelements.",
 				newLogFieldInt("subelements_number", len(names)))
 			return NewNativeType(protoVer, TypeCustom)
 		}
@@ -227,7 +227,7 @@ func getCassandraLongType(name string, protoVer byte, logger StructuredLogger) T
 		subType := getCassandraLongType(strings.TrimSpace(names[0]), protoVer, logger)
 		dim, err := strconv.Atoi(strings.TrimSpace(names[1]))
 		if err != nil {
-			logger.Warning("Error parsing vector dimensions: %v", newLogFieldError("error", err))
+			logger.Warning("Error parsing vector dimensions.", newLogFieldError("error", err))
 			return NewNativeType(protoVer, TypeCustom)
 		}
 
@@ -262,7 +262,7 @@ func getCassandraType(name string, protoVer byte, logger StructuredLogger) TypeI
 	} else if strings.HasPrefix(name, "map<") {
 		names := splitCQLCompositeTypes(name, "map")
 		if len(names) != 2 {
-			logger.Warning("Error parsing map type, it has %d subelements, expecting 2",
+			logger.Warning("Error parsing map type, expected 2 subelements.",
 				newLogFieldInt("subelements_number", len(names)))
 			return NewNativeType(protoVer, TypeCustom)
 		}