Initial Logging Output Update (#2246)

This attempts to update logging statements to make them consistent
through out the code base. It also adds additional context to messages
where possible, simplifies messages, and updates level where necessary.

pkg/agent/config/config.go

@@ -39,7 +39,7 @@ func Get(ctx context.Context, agent cmds.Agent, proxy proxy.Proxy) *config.Node
 	for {
 		agentConfig, err := get(&agent, proxy)
 		if err != nil {
-			logrus.Error(err)
+			logrus.Errorf("Failed to retrieve agent config: %v", err)
 			select {
 			case <-time.After(5 * time.Second):
 				continue
@@ -286,7 +286,7 @@ func locateOrGenerateResolvConf(envInfo *cmds.Agent) string {
 
 	tmpConf := filepath.Join(os.TempDir(), version.Program+"-resolv.conf")
 	if err := ioutil.WriteFile(tmpConf, []byte("nameserver 8.8.8.8\n"), 0444); err != nil {
-		logrus.Error(err)
+		logrus.Errorf("Failed to write %s: %v", tmpConf, err)
 		return ""
 	}
 	return tmpConf

pkg/agent/containerd/containerd.go

@@ -105,6 +105,7 @@ func Run(ctx context.Context, cfg *config.Node) error {
 		case <-time.After(time.Second):
 		}
 	}
+	logrus.Info("Containerd is now running")
 
 	return preloadImages(ctx, cfg)
 }

pkg/agent/flannel/setup.go

@@ -86,12 +86,13 @@ func Run(ctx context.Context, nodeConfig *config.Node, nodes v1.NodeInterface) e
 			break
 		}
 		if err == nil {
-			logrus.Infof("waiting for node %s CIDR not assigned yet", nodeName)
+			logrus.Info("Waiting for node " + nodeName + " CIDR not assigned yet")
 		} else {
-			logrus.Infof("waiting for node %s: %v", nodeName, err)
+			logrus.Infof("Waiting for node %s: %v", nodeName, err)
 		}
 		time.Sleep(2 * time.Second)
 	}
+	logrus.Info("Node CIDR assigned for: " + nodeName)
 
 	go func() {
 		err := flannel(ctx, nodeConfig.FlannelIface, nodeConfig.FlannelConf, nodeConfig.AgentConfig.KubeConfigKubelet)

pkg/agent/proxy/apiproxy.go

@@ -87,7 +87,7 @@ func (p *proxy) setSupervisorPort(addresses []string) []string {
 	for _, address := range addresses {
 		h, _, err := sysnet.SplitHostPort(address)
 		if err != nil {
-			logrus.Errorf("failed to parse address %s, dropping: %v", address, err)
+			logrus.Errorf("Failed to parse address %s, dropping: %v", address, err)
 			continue
 		}
 		newAddresses = append(newAddresses, sysnet.JoinHostPort(h, p.supervisorPort))

pkg/agent/run.go

@@ -177,7 +177,7 @@ func validate() error {
 	}
 
 	if !strings.Contains(string(cgroups), "cpuset") {
-		logrus.Warn("Failed to find cpuset cgroup, you may need to add \"cgroup_enable=cpuset\" to your linux cmdline (/boot/cmdline.txt on a Raspberry Pi)")
+		logrus.Warn(`Failed to find cpuset cgroup, you may need to add "cgroup_enable=cpuset" to your linux cmdline (/boot/cmdline.txt on a Raspberry Pi)`)
 	}
 
 	if !strings.Contains(string(cgroups), "memory") {

pkg/agent/syssetup/setup.go

@@ -12,18 +12,18 @@ import (
 
 func loadKernelModule(moduleName string) {
 	if _, err := os.Stat("/sys/module/" + moduleName); err == nil {
-		logrus.Infof("module %s was already loaded", moduleName)
+		logrus.Info("Module " + moduleName + " was already loaded")
 		return
 	}
 
 	if err := exec.Command("modprobe", moduleName).Run(); err != nil {
-		logrus.Warnf("failed to start %s module", moduleName)
+		logrus.Warn("Failed to start " + moduleName + " module")
 	}
 }
 
 func enableSystemControl(file string) {
 	if err := ioutil.WriteFile(file, []byte("1"), 0640); err != nil {
-		logrus.Warnf("failed to write value 1 at %s: %v", file, err)
+		logrus.Warnf("Failed to write value 1 at "+file+": %v", err)
 	}
 }
 

pkg/agent/tunnel/tunnel.go

@@ -96,7 +96,7 @@ func Setup(ctx context.Context, config *config.Node, proxy proxy.Proxy) error {
 				ResourceVersion: "0",
 			})
 			if err != nil {
-				logrus.Errorf("Unable to watch for tunnel endpoints: %v", err)
+				logrus.Warnf("Unable to watch for tunnel endpoints: %v", err)
 				continue connect
 			}
 		watching:
@@ -151,7 +151,7 @@ func Setup(ctx context.Context, config *config.Node, proxy proxy.Proxy) error {
 
 	select {
 	case <-ctx.Done():
-		logrus.Error("tunnel context canceled while waiting for connection")
+		logrus.Error("Tunnel context canceled while waiting for connection")
 		return ctx.Err()
 	case <-wait:
 	}

pkg/cli/agent/agent.go

@@ -54,7 +54,7 @@ func Run(ctx *cli.Context) error {
 		cmds.AgentConfig.NodeIP = netutil.GetIPFromInterface(cmds.AgentConfig.FlannelIface)
 	}
 
-	logrus.Infof("Starting "+version.Program+" agent %s", ctx.App.Version)
+	logrus.Info("Starting " + version.Program + " agent " + ctx.App.Version)
 
 	dataDir, err := datadir.LocalHome(cmds.AgentConfig.DataDir, cmds.AgentConfig.Rootless)
 	if err != nil {

pkg/cli/server/server.go

@@ -231,7 +231,7 @@ func run(app *cli.Context, cfg *cmds.Server) error {
 		return errors.Wrap(err, "Invalid tls-cipher-suites")
 	}
 
-	logrus.Info("Starting "+version.Program+" ", app.App.Version)
+	logrus.Info("Starting " + version.Program + " " + app.App.Version)
 	notifySocket := os.Getenv("NOTIFY_SOCKET")
 	os.Unsetenv("NOTIFY_SOCKET")
 
@@ -242,7 +242,8 @@ func run(app *cli.Context, cfg *cmds.Server) error {
 
 	go func() {
 		<-serverConfig.ControlConfig.Runtime.APIServerReady
-		logrus.Info("" + version.Program + " is up and running")
+		logrus.Info("Kube API server is now running")
+		logrus.Info(version.Program + " is up and running")
 		if notifySocket != "" {
 			os.Setenv("NOTIFY_SOCKET", notifySocket)
 			systemd.SdNotify(true, "READY=1\n")

pkg/cloudprovider/instances.go

@@ -63,7 +63,7 @@ func (k *k3s) NodeAddresses(ctx context.Context, name types.NodeName) ([]corev1.
 	if node.Labels[InternalIPLabel] != "" {
 		addresses = append(addresses, corev1.NodeAddress{Type: corev1.NodeInternalIP, Address: node.Labels[InternalIPLabel]})
 	} else {
-		logrus.Infof("couldn't find node internal ip label on node %s", name)
+		logrus.Infof("Couldn't find node internal ip label on node %s", name)
 	}
 
 	// check external address
@@ -75,7 +75,7 @@ func (k *k3s) NodeAddresses(ctx context.Context, name types.NodeName) ([]corev1.
 	if node.Labels[HostnameLabel] != "" {
 		addresses = append(addresses, corev1.NodeAddress{Type: corev1.NodeHostName, Address: node.Labels[HostnameLabel]})
 	} else {
-		logrus.Infof("couldn't find node hostname label on node %s", name)
+		logrus.Infof("Couldn't find node hostname label on node %s", name)
 	}
 
 	return addresses, nil

pkg/cluster/managed.go

@@ -25,7 +25,7 @@ func (c *Cluster) testClusterDB(ctx context.Context) (<-chan struct{}, error) {
 			if err := c.managedDB.Test(ctx, c.clientAccessInfo); err != nil {
 				logrus.Infof("Failed to test data store connection: %v", err)
 			} else {
-				logrus.Infof("Data store connection OK")
+				logrus.Info(c.managedDB.EndpointName() + " data store connection OK")
 				return
 			}
 

pkg/deploy/controller.go

@@ -70,7 +70,7 @@ func (w *watcher) start(ctx context.Context) {
 		if err := w.listFiles(force); err == nil {
 			force = false
 		} else {
-			logrus.Errorf("failed to process config: %v", err)
+			logrus.Errorf("Failed to process config: %v", err)
 		}
 		select {
 		case <-ctx.Done():

pkg/etcd/etcd.go

@@ -134,7 +134,7 @@ func (e *ETCD) Reset(ctx context.Context, clientAccessInfo *clientaccess.Info) e
 				}
 
 				if len(members.Members) == 1 && members.Members[0].Name == e.name {
-					logrus.Infof("etcd is running, restart without --cluster-reset flag now. Backup and delete ${datadir}/server/db on each peer etcd server and rejoin the nodes")
+					logrus.Infof("Etcd is running, restart without --cluster-reset flag now. Backup and delete ${datadir}/server/db on each peer etcd server and rejoin the nodes")
 					os.Exit(0)
 				}
 			}
@@ -211,7 +211,7 @@ func (e *ETCD) join(ctx context.Context, clientAccessInfo *clientaccess.Info) er
 
 	members, err := client.MemberList(ctx)
 	if err != nil {
-		logrus.Errorf("failed to get member list from cluster, will assume this member is already added")
+		logrus.Errorf("Failed to get member list from etcd cluster. Will assume this member is already added")
 		members = &etcd.MemberListResponse{
 			Members: append(memberList.Members, &etcdserverpb.Member{
 				Name:     e.name,
@@ -552,14 +552,14 @@ func (e *ETCD) snapshot(ctx context.Context) {
 	logrus.Infof("Snapshot retention check")
 	snapshotDir, err := snapshotDir(e.config)
 	if err != nil {
-		logrus.Errorf("failed to get the snapshot dir: %v", err)
+		logrus.Errorf("Failed to get the snapshot dir: %v", err)
 		return
 	}
 	logrus.Infof("Taking etcd snapshot at %s", snapshotTime.String())
 	sManager := snapshot.NewV3(nil)
 	tlsConfig, err := toTLSConfig(e.runtime)
 	if err != nil {
-		logrus.Errorf("failed to get tls config for etcd: %v", err)
+		logrus.Errorf("Failed to get tls config for etcd: %v", err)
 		return
 	}
 	etcdConfig := etcd.Config{
@@ -570,11 +570,11 @@ func (e *ETCD) snapshot(ctx context.Context) {
 	snapshotPath := filepath.Join(snapshotDir, snapshotPrefix+strconv.Itoa(int(snapshotTime.Unix())))
 
 	if err := sManager.Save(ctx, etcdConfig, snapshotPath); err != nil {
-		logrus.Errorf("failed to save snapshot %s: %v", snapshotPath, err)
+		logrus.Errorf("Failed to save snapshot %s: %v", snapshotPath, err)
 		return
 	}
 	if err := snapshotRetention(e.config.EtcdSnapshotRetention, snapshotDir); err != nil {
-		logrus.Errorf("failed to apply snapshot retention: %v", err)
+		logrus.Errorf("Failed to apply snapshot retention: %v", err)
 		return
 	}
 }
@@ -593,7 +593,7 @@ func (e *ETCD) Restore(ctx context.Context) error {
 	// check the old etcd data dir
 	oldDataDir := dataDir(e.config) + "-old"
 	if s, err := os.Stat(oldDataDir); err == nil && s.IsDir() {
-		logrus.Infof("etcd already restored from a snapshot. Restart without --snapshot-restore-path flag. Backup and delete ${datadir}/server/db on each peer etcd server and rejoin the nodes")
+		logrus.Infof("Etcd already restored from a snapshot. Restart without --snapshot-restore-path flag. Backup and delete ${datadir}/server/db on each peer etcd server and rejoin the nodes")
 		os.Exit(0)
 	} else if os.IsNotExist(err) {
 		if e.config.ClusterResetRestorePath == "" {

pkg/netutil/iface.go

@@ -13,7 +13,7 @@ func GetIPFromInterface(ifaceName string) string {
 	if err != nil {
 		logrus.Warn(errors.Wrap(err, "unable to get global unicast ip from interface name"))
 	} else {
-		logrus.Infof("found ip %s from iface %s", ip, ifaceName)
+		logrus.Infof("Found ip %s from iface %s", ip, ifaceName)
 	}
 	return ip
 }

pkg/node/controller.go

@@ -52,7 +52,7 @@ func (h *handler) updateHosts(node *core.Node, removed bool) (*core.Node, error)
 		}
 	}
 	if nodeAddress == "" {
-		logrus.Errorf("No InternalIP found for node %s", node.Name)
+		logrus.Errorf("No InternalIP found for node " + node.Name)
 		return nil, nil
 	}
 

pkg/rootlessports/controller.go

@@ -34,7 +34,7 @@ func Register(ctx context.Context, serviceController coreClients.ServiceControll
 		if err == nil {
 			break
 		} else {
-			logrus.Infof("waiting for rootless API socket %s: %v", rootless.Sock, err)
+			logrus.Infof("Waiting for rootless API socket %s: %v", rootless.Sock, err)
 			time.Sleep(1 * time.Second)
 		}
 	}

pkg/server/auth.go

@@ -21,15 +21,22 @@ func hasRole(mustRoles []string, roles []string) bool {
 }
 
 func doAuth(roles []string, serverConfig *config.Control, next http.Handler, rw http.ResponseWriter, req *http.Request) {
-	if serverConfig == nil || serverConfig.Runtime.Authenticator == nil {
+	switch {
-		logrus.Errorf("authenticate not initialized")
+	case serverConfig == nil:
+		logrus.Errorf("Authenticate not initialized: serverConfig is nil")
 		rw.WriteHeader(http.StatusUnauthorized)
 		return
+	case serverConfig.Runtime.Authenticator == nil:
+		logrus.Errorf("Authenticate not initialized: serverConfig.Runtime.Authenticator is nil")
+		rw.WriteHeader(http.StatusUnauthorized)
+		return
+	default:
+		//
 	}
 
 	resp, ok, err := serverConfig.Runtime.Authenticator.AuthenticateRequest(req)
 	if err != nil {
-		logrus.Errorf("failed to authenticate request: %v", err)
+		logrus.Errorf("Failed to authenticate request from %s: %v", req.RemoteAddr, err)
 		rw.WriteHeader(http.StatusInternalServerError)
 		return
 	}

pkg/server/server.go

@@ -284,7 +284,7 @@ func writeKubeConfig(certs string, config *Config) error {
 
 	if isSymlink(kubeConfigSymlink) {
 		if err := os.Remove(kubeConfigSymlink); err != nil {
-			logrus.Errorf("failed to remove kubeconfig symlink")
+			logrus.Errorf("Failed to remove kubeconfig symlink")
 		}
 	}
 
@@ -301,7 +301,7 @@ func writeKubeConfig(certs string, config *Config) error {
 		if err == nil {
 			util.SetFileModeForPath(kubeConfig, os.FileMode(mode))
 		} else {
-			logrus.Errorf("failed to set %s to mode %s: %v", kubeConfig, os.FileMode(mode), err)
+			logrus.Errorf("Failed to set %s to mode %s: %v", kubeConfig, os.FileMode(mode), err)
 		}
 	} else {
 		util.SetFileModeForPath(kubeConfig, os.FileMode(0600))
@@ -309,7 +309,7 @@ func writeKubeConfig(certs string, config *Config) error {
 
 	if kubeConfigSymlink != kubeConfig {
 		if err := writeConfigSymlink(kubeConfig, kubeConfigSymlink); err != nil {
-			logrus.Errorf("failed to write kubeconfig symlink: %v", err)
+			logrus.Errorf("Failed to write kubeconfig symlink: %v", err)
 		}
 	}
 
@@ -348,7 +348,7 @@ func printToken(httpsPort int, advertiseIP, prefix, cmd string) {
 	if ip == "" {
 		hostIP, err := net.ChooseHostInterface()
 		if err != nil {
-			logrus.Error(err)
+			logrus.Errorf("Failed to choose interface: %v", err)
 		}
 		ip = hostIP.String()
 	}
@@ -433,7 +433,7 @@ func setMasterRoleLabel(ctx context.Context, nodes v1.NodeClient) error {
 		node.Labels[MasterRoleLabelKey] = "true"
 		_, err = nodes.Update(node)
 		if err == nil {
-			logrus.Infof("master role label has been set successfully on node: %s", nodeName)
+			logrus.Infof("Master role label has been set successfully on node: %s", nodeName)
 			break
 		}
 		select {
@@ -450,7 +450,7 @@ func setClusterDNSConfig(ctx context.Context, controlConfig *Config, configMap v
 	// check if configmap already exists
 	_, err := configMap.Get("kube-system", "cluster-dns", metav1.GetOptions{})
 	if err == nil {
-		logrus.Infof("cluster dns configmap already exists")
+		logrus.Infof("Cluster dns configmap already exists")
 		return nil
 	}
 	clusterDNS := controlConfig.ControlConfig.ClusterDNS
@@ -472,7 +472,7 @@ func setClusterDNSConfig(ctx context.Context, controlConfig *Config, configMap v
 	for {
 		_, err = configMap.Create(c)
 		if err == nil {
-			logrus.Infof("cluster dns configmap has been set successfully")
+			logrus.Infof("Cluster dns configmap has been set successfully")
 			break
 		}
 		logrus.Infof("Waiting for master node %s startup: %v", nodeName, err)