logging cleanup - start with lowercase unless reporting error or warning

api.go

@@ -957,7 +957,7 @@ func (api *API) validateShardOwnership(indexName string, shard uint64) error {
 }
 
 func (api *API) indexField(indexName string, fieldName string, shard uint64) (*Index, *Field, error) {
-	api.server.logger.Printf("importing: %v %v %v", indexName, fieldName, shard)
+	api.server.logger.Debugf("importing: %v %v %v", indexName, fieldName, shard)
 
 	// Find the Index.
 	index := api.holder.Index(indexName)

cluster.go

@@ -347,8 +347,6 @@ func (c *cluster) unprotectedUpdateCoordinator(n *Node) bool {
 // addNode adds a node to the Cluster and updates and saves the
 // new topology. unprotected.
 func (c *cluster) addNode(node *Node) error {
-	c.logger.Printf("add node %s to cluster on %s", node, c.Node)
-
 	// If the node being added is the coordinator, set it for this node.
 	if node.IsCoordinator {
 		c.Coordinator = node.ID
@@ -481,7 +479,7 @@ func (c *cluster) setNodeState(state string) error { // nolint: unparam
 		State:  state,
 	}
 
-	c.logger.Printf("Sending State %s (%s)", state, c.Coordinator)
+	c.logger.Printf("sending state %s (%s)", state, c.Coordinator)
 	if err := c.sendTo(c.coordinatorNode(), ns); err != nil {
 		return fmt.Errorf("sending node state error: err=%s", err)
 	}
@@ -970,7 +968,6 @@ func (c *cluster) close() error {
 }
 
 func (c *cluster) markAsJoined() {
-	c.logger.Printf("mark node as joined (received coordinator update)")
 	if !c.joined {
 		c.joined = true
 		close(c.joining)
@@ -1069,7 +1066,6 @@ func (c *cluster) unprotectedSetStateAndBroadcast(state string) error {
 	}
 	// Broadcast cluster status changes to the cluster.
 	status := c.unprotectedStatus()
-	c.logger.Printf("broadcasting ClusterStatus: %s", status)
 	return c.broadcaster.SendSync(status) // TODO fix c.Status
 
 }
@@ -1246,7 +1242,7 @@ func (c *cluster) followResizeInstruction(instr *ResizeInstruction) error {
 		return errors.Wrap(err, "merging cluster status")
 	}
 
-	c.logger.Printf("MergeClusterStatus done, start goroutine")
+	c.logger.Printf("done MergeClusterStatus, start goroutine")
 
 	// The actual resizing runs in a goroutine because we don't want to block
 	// the distribution of other ResizeInstructions to the rest of the cluster.
@@ -1266,7 +1262,7 @@ func (c *cluster) followResizeInstruction(instr *ResizeInstruction) error {
 		if err := func() error {
 
 			// Sync the schema received in the resize instruction.
-			c.logger.Printf("Holder ApplySchema")
+			c.logger.Debugf("holder applySchema")
 			if err := c.holder.applySchema(instr.Schema); err != nil {
 				return errors.Wrap(err, "applying schema")
 			}
@@ -1651,17 +1647,17 @@ func (c *cluster) ReceiveEvent(e *NodeEvent) (err error) {
 
 	switch e.Event {
 	case NodeJoin:
-		c.logger.Printf("nodeJoin of %s on %s", e.Node.URI, c.Node.URI)
+		c.logger.Debugf("nodeJoin of %s on %s", e.Node.URI, c.Node.URI)
 		// Ignore the event if this is not the coordinator.
 		if !c.isCoordinator() {
 			return nil
 		}
 		return c.nodeJoin(e.Node)
 	case NodeLeave:
-		c.logger.Printf("received node leave on %s: %s, uri: %v", c.Node, e.Node, e.Node.URI)
 		c.mu.Lock()
 		defer c.mu.Unlock()
 		if c.unprotectedIsCoordinator() {
+			c.logger.Printf("received node leave: %v", e.Node)
 			// if removeNodeBasicSorted succeeds, that means that the node was
 			// not already removed by a removeNode request. We treat this as the
 			// host being temporarily unavailable, and expect it to come back
@@ -1673,7 +1669,6 @@ func (c *cluster) ReceiveEvent(e *NodeEvent) (err error) {
 				err = c.unprotectedSetStateAndBroadcast(c.determineClusterState())
 			}
 		}
-		c.logger.Printf("finished node leave on %s: %s, uri: %v", c.Node, e.Node, e.Node.URI)
 	case NodeUpdate:
 		c.logger.Printf("received node update event: id: %v, string: %v, uri: %v", e.Node.ID, e.Node.String(), e.Node.URI)
 		// NodeUpdate is intentionally not implemented.
@@ -1686,7 +1681,7 @@ func (c *cluster) ReceiveEvent(e *NodeEvent) (err error) {
 func (c *cluster) nodeJoin(node *Node) error {
 	c.mu.Lock()
 	defer c.mu.Unlock()
-	c.logger.Printf("NodeJoin event on coordinator, node: %s, id: %s", node.URI, node.ID)
+	c.logger.Printf("node join event on coordinator, node: %s, id: %s", node.URI, node.ID)
 	if c.needTopologyAgreement() {
 		// A host that is not part of the topology can't be added to the STARTING cluster.
 		if !c.Topology.ContainsID(node.ID) {
@@ -1726,7 +1721,7 @@ func (c *cluster) nodeJoin(node *Node) error {
 	// the cluster.
 	if cnode := c.unprotectedNodeByID(node.ID); cnode != nil {
 		if cnode.URI != node.URI {
-			c.logger.Printf("Node: %v changed URI from %s to %s", cnode.ID, cnode.URI, node.URI)
+			c.logger.Printf("node: %v changed URI from %s to %s", cnode.ID, cnode.URI, node.URI)
 			cnode.URI = node.URI
 		}
 		return c.unprotectedSetStateAndBroadcast(c.determineClusterState())

fragment.go

@@ -1734,7 +1734,6 @@ func (f *fragment) snapshot() error {
 // f.mu must be locked when calling it.
 func unprotectedWriteToFragment(f *fragment, bm *roaring.Bitmap) error { // nolint: interfacer
 
-	f.Logger.Printf("fragment: snapshotting %s/%s/%s/%d", f.index, f.field, f.view, f.shard)
 	completeMessage := fmt.Sprintf("fragment: snapshot complete %s/%s/%s/%d", f.index, f.field, f.view, f.shard)
 	start := time.Now()
 	defer track(start, completeMessage, f.stats, f.Logger)

holder.go

@@ -474,7 +474,7 @@ func (h *Holder) flushCaches() {
 					}
 
 					if err := fragment.FlushCache(); err != nil {
-						h.Logger.Printf("error flushing cache: err=%s, path=%s", err, fragment.cachePath())
+						h.Logger.Printf("ERROR flushing cache: err=%s, path=%s", err, fragment.cachePath())
 					}
 				}
 			}
@@ -535,7 +535,7 @@ func (h *Holder) setFileLimit() {
 			h.Logger.Printf("ERROR checking open file limit: %s", err)
 		} else {
 			if oldLimit.Cur < fileLimit {
-				h.Logger.Printf("WARNING: Tried to set open file limit to %d, but it is %d. You may consider running \"sudo ulimit -n %d\" before starting Pilosa to avoid \"too many open files\" error. See https://www.pilosa.com/docs/administration/#open-file-limits for more information.", fileLimit, oldLimit.Cur, fileLimit)
+				h.Logger.Printf("WARNING: Tried to set open file limit to %d, but it is %d. You may consider running \"sudo ulimit -n %d\" before starting Pilosa to avoid \"too many open files\" error. See https://www.pilosa.com/docs/latest/administration/#open-file-limits for more information.", fileLimit, oldLimit.Cur, fileLimit)
 			}
 		}
 	}

server.go

@@ -585,7 +585,6 @@ func (s *Server) SendSync(m Message) error {
 	msg = append([]byte{getMessageType(m)}, msg...)
 	for _, node := range s.cluster.nodes {
 		node := node
-		s.logger.Printf("SendSync to: %s", node.URI)
 		// Don't forward the message to ourselves.
 		if s.uri == node.URI {
 			continue
@@ -606,7 +605,6 @@ func (s *Server) SendAsync(m Message) error {
 
 // SendTo represents an implementation of Broadcaster.
 func (s *Server) SendTo(to *Node, m Message) error {
-	s.logger.Printf("SendTo: %s", to.URI)
 	msg, err := s.serializer.Marshal(m)
 	if err != nil {
 		return fmt.Errorf("marshaling message: %v", err)
@@ -658,7 +656,7 @@ func (s *Server) mergeRemoteStatus(ns *NodeStatus) error {
 			// if we don't know about a field locally, log an error because
 			// fields should be created and synced prior to shard creation
 			if f == nil {
-				s.logger.Printf("Local Field not found: %s/%s", is.Name, fs.Name)
+				s.logger.Printf("local field not found: %s/%s", is.Name, fs.Name)
 				continue
 			}
 			if err := f.AddRemoteAvailableShards(fs.AvailableShards); err != nil {
@@ -703,7 +701,7 @@ func (s *Server) monitorDiagnostics() {
 		s.diagnostics.CheckVersion()
 		err = s.diagnostics.Flush()
 		if err != nil {
-			s.logger.Printf("Diagnostics error: %s", err)
+			s.logger.Printf("diagnostics error: %s", err)
 		}
 	}
 

server/server.go

@@ -142,7 +142,7 @@ func (m *Command) Start() (err error) {
 	go func() {
 		err := m.Handler.Serve()
 		if err != nil {
-			m.logger.Printf("Handler serve error: %v", err)
+			m.logger.Printf("handler serve error: %v", err)
 		}
 	}()
 
@@ -151,7 +151,7 @@ func (m *Command) Start() (err error) {
 		return errors.Wrap(err, "opening server")
 	}
 
-	m.logger.Printf("Listening as %s\n", m.API.Node().URI)
+	m.logger.Printf("listening as %s\n", m.API.Node().URI)
 
 	return nil
 }
@@ -163,13 +163,13 @@ func (m *Command) Wait() error {
 	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
 	select {
 	case sig := <-c:
-		m.logger.Printf("Received %s; gracefully shutting down...\n", sig.String())
+		m.logger.Printf("received signal '%s', gracefully shutting down...\n", sig.String())
 
 		// Second signal causes a hard shutdown.
 		go func() { <-c; os.Exit(1) }()
 		return errors.Wrap(m.Close(), "closing command")
 	case <-m.done:
-		m.logger.Printf("Server closed externally")
+		m.logger.Printf("server closed externally")
 		return nil
 	}
 }

translate.go

@@ -195,12 +195,11 @@ func (s *TranslateFile) handlePrimaryStoreEvent(ev primaryStoreEvent) error {
 	}
 
 	// Stop translate store replication.
-	s.logger.Printf("stop monitor replication")
 	close(s.replicationClosing)
 	s.repWG.Wait()
 
 	// Set the primary node for translate store replication.
-	s.logger.Printf("set primary translate store to %s", ev.id)
+	s.logger.Debugf("set primary translate store to %s", ev.id)
 	s.primaryID = ev.id
 	if ev.id == "" {
 		s.PrimaryTranslateStore = nil
@@ -209,7 +208,6 @@ func (s *TranslateFile) handlePrimaryStoreEvent(ev primaryStoreEvent) error {
 	}
 
 	// Start translate store replication. Stream from primary, if available.
-	s.logger.Printf("start monitor replication")
 	if s.PrimaryTranslateStore != nil {
 		s.replicationClosing = make(chan struct{})
 		s.repWG.Add(1)
@@ -386,7 +384,6 @@ func (s *TranslateFile) monitorReplication() {
 // monitorPrimaryStoreEvents is executed in a separate goroutine and listens for changes
 // to the primary store assignment.
 func (s *TranslateFile) monitorPrimaryStoreEvents() {
-	s.logger.Printf("monitor primary store events")
 	// Keep handling events until the store closes.
 	for {
 		select {
@@ -404,7 +401,7 @@ func (s *TranslateFile) replicate(ctx context.Context) error {
 	off := s.size()
 
 	// Connect to remote primary.
-	s.logger.Printf("pilosa: replicating from offset %d", off)
+	s.logger.Debugf("pilosa: replicating from offset %d", off)
 	rc, err := s.PrimaryTranslateStore.Reader(ctx, off)
 	if err != nil {
 		return err