Split log statements into more buckets for better control

docs/logging.md

@@ -0,0 +1,25 @@
+Logging Conventions
+===================
+
+The following conventions for the glog levels to use.  glog is globally prefered to "log" for better runtime control.
+
+* glog.Errorf() - Always an error
+* glog.Warningf() - Something unexpected, but probably not an error
+* glog.Infof / glog.V(0) - Generally useful for this to ALWAYS be visible to an operator
+ * Programmer errors
+ * Logging extra info about a panic
+ * CLI argument handling
+* glog.V(1) - A reasonable default log level if you don't want verbosity.
+ * Information about config (listening on X, watching Y)
+  * Errors that repeat frequently that relate to conditions that can be corrected (pod detected as unhealthy)
+* glog.V(2) - Useful steady state information about the service and important log messages that may correlate to significant changes in the system.  This is the recommended default log level for most systems.
+ * Logging HTTP requests and their exit code
+ * System state changing (killing pod)
+ * Controller state change events (starting pods)
+ * Scheduler log messages
+* glog.V(3) - Extended information about changes
+  * More info about system state changes
+* glog.V(4) - Debug level verbosity (for now)
+ * Logging in particularly thorny parts of code where you may want to come back later and check it
+
+As per the comments, the practical default level is V(2).  Developers and QE environments may wish to run at V(3) or V(4).

pkg/apiserver/errors.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/api"
 	"github.com/GoogleCloudPlatform/kubernetes/pkg/tools"
+	"github.com/golang/glog"
 )
 
 // statusError is an object that can be converted into an api.Status
@@ -44,6 +45,11 @@ func errToAPIStatus(err error) *api.Status {
 		case tools.IsEtcdTestFailed(err):
 			status = http.StatusConflict
 		}
+		// Log errors that were not converted to an error status
+		// by REST storage - these typically indicate programmer
+		// error by not using pkg/api/errors, or unexpected failure
+		// cases.
+		glog.V(1).Infof("An unchecked error was received: %v", err)
 		return &api.Status{
 			Status:  api.StatusFailure,
 			Code:    status,

pkg/client/cache/reflector.go

@@ -166,6 +166,6 @@ func (r *Reflector) watchHandler(w watch.Interface, resourceVersion *uint64) err
 		glog.Errorf("unexpected watch close - watch lasted less than a second and no items received")
 		return errors.New("very short watch")
 	}
-	glog.Infof("watch close - %v total items received", eventCount)
+	glog.V(4).Infof("watch close - %v total items received", eventCount)
 	return nil
 }

pkg/cloudprovider/plugins.go

@@ -42,7 +42,7 @@ func RegisterCloudProvider(name string, cloud Factory) {
 	if found {
 		glog.Fatalf("Cloud provider %q was registered twice", name)
 	}
-	glog.Infof("Registered cloud provider %q", name)
+	glog.V(1).Infof("Registered cloud provider %q", name)
 	providers[name] = cloud
 }
 

pkg/controller/replication_controller.go

@@ -115,7 +115,7 @@ func (rm *ReplicationManager) watchControllers(resourceVersion *uint64) {
 				// that called us call us again.
 				return
 			}
-			glog.Infof("Got watch: %#v", event)
+			glog.V(4).Infof("Got watch: %#v", event)
 			rc, ok := event.Object.(*api.ReplicationController)
 			if !ok {
 				glog.Errorf("unexpected object: %#v", event.Object)
@@ -125,7 +125,7 @@ func (rm *ReplicationManager) watchControllers(resourceVersion *uint64) {
 			*resourceVersion = rc.ResourceVersion + 1
 			// Sync even if this is a deletion event, to ensure that we leave
 			// it in the desired state.
-			glog.Infof("About to sync from watch: %v", rc.ID)
+			glog.V(4).Infof("About to sync from watch: %v", rc.ID)
 			rm.syncHandler(*rc)
 		}
 	}
@@ -153,7 +153,7 @@ func (rm *ReplicationManager) syncReplicationController(controllerSpec api.Repli
 		diff *= -1
 		wait := sync.WaitGroup{}
 		wait.Add(diff)
-		glog.Infof("Too few replicas, creating %d\n", diff)
+		glog.V(2).Infof("Too few replicas, creating %d\n", diff)
 		for i := 0; i < diff; i++ {
 			go func() {
 				defer wait.Done()
@@ -162,7 +162,7 @@ func (rm *ReplicationManager) syncReplicationController(controllerSpec api.Repli
 		}
 		wait.Wait()
 	} else if diff > 0 {
-		glog.Infof("Too many replicas, deleting %d\n", diff)
+		glog.V(2).Infof("Too many replicas, deleting %d\n", diff)
 		wait := sync.WaitGroup{}
 		wait.Add(diff)
 		for i := 0; i < diff; i++ {
@@ -191,7 +191,7 @@ func (rm *ReplicationManager) synchronize() {
 	for ix := range controllerSpecs {
 		go func(ix int) {
 			defer wg.Done()
-			glog.Infof("periodic sync of %v", controllerSpecs[ix].ID)
+			glog.V(4).Infof("periodic sync of %v", controllerSpecs[ix].ID)
 			err := rm.syncHandler(controllerSpecs[ix])
 			if err != nil {
 				glog.Errorf("Error synchronizing: %#v", err)

pkg/httplog/log.go

@@ -148,7 +148,7 @@ func (rl *respLogger) Addf(format string, data ...interface{}) {
 // Log is intended to be called once at the end of your request handler, via defer
 func (rl *respLogger) Log() {
 	latency := time.Since(rl.startTime)
-	glog.Infof("%s %s: (%v) %v%v%v", rl.req.Method, rl.req.RequestURI, latency, rl.status, rl.statusStack, rl.addedInfo)
+	glog.V(2).Infof("%s %s: (%v) %v%v%v", rl.req.Method, rl.req.RequestURI, latency, rl.status, rl.statusStack, rl.addedInfo)
 }
 
 // Header implements http.ResponseWriter.

pkg/kubelet/config/config.go

@@ -168,9 +168,9 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de
 	switch update.Op {
 	case kubelet.ADD, kubelet.UPDATE:
 		if update.Op == kubelet.ADD {
-			glog.Infof("Adding new pods from source %s : %v", source, update.Pods)
+			glog.V(4).Infof("Adding new pods from source %s : %v", source, update.Pods)
 		} else {
-			glog.Infof("Updating pods from source %s : %v", source, update.Pods)
+			glog.V(4).Infof("Updating pods from source %s : %v", source, update.Pods)
 		}
 
 		filtered := filterInvalidPods(update.Pods, source)
@@ -193,7 +193,7 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de
 		}
 
 	case kubelet.REMOVE:
-		glog.Infof("Removing a pod %v", update)
+		glog.V(4).Infof("Removing a pod %v", update)
 		for _, value := range update.Pods {
 			name := value.Name
 			if existing, found := pods[name]; found {
@@ -206,7 +206,7 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de
 		}
 
 	case kubelet.SET:
-		glog.Infof("Setting pods for source %s : %v", source, update)
+		glog.V(4).Infof("Setting pods for source %s : %v", source, update)
 		// Clear the old map entries by just creating a new map
 		oldPods := pods
 		pods = make(map[string]*kubelet.Pod)
@@ -238,7 +238,7 @@ func (s *podStorage) merge(source string, change interface{}) (adds, updates, de
 		}
 
 	default:
-		glog.Infof("Received invalid update type: %v", update)
+		glog.Warningf("Received invalid update type: %v", update)
 
 	}
 
@@ -259,7 +259,7 @@ func filterInvalidPods(pods []kubelet.Pod, source string) (filtered []*kubelet.P
 			errors = append(errors, errs...)
 		}
 		if len(errors) > 0 {
-			glog.Warningf("Pod %d from %s failed validation, ignoring: %v", i+1, source, errors)
+			glog.Warningf("Pod %d (%s) from %s failed validation, ignoring: %v", i+1, pods[i].Name, source, errors)
 			continue
 		}
 		filtered = append(filtered, &pods[i])

pkg/kubelet/config/etcd.go

@@ -54,7 +54,7 @@ func NewSourceEtcd(key string, client tools.EtcdClient, updates chan<- interface
 		helper:  helper,
 		updates: updates,
 	}
-	glog.Infof("Watching etcd for %s", key)
+	glog.V(1).Infof("Watching etcd for %s", key)
 	go util.Forever(source.run, time.Second)
 	return source
 }
@@ -78,7 +78,7 @@ func (s *SourceEtcd) run() {
 				continue
 			}
 
-			glog.Infof("Received state from etcd watch: %+v", pods)
+			glog.V(4).Infof("Received state from etcd watch: %+v", pods)
 			s.updates <- kubelet.PodUpdate{pods, kubelet.SET}
 		}
 	}

pkg/kubelet/config/file.go

@@ -45,7 +45,7 @@ func NewSourceFile(path string, period time.Duration, updates chan<- interface{}
 		path:    path,
 		updates: updates,
 	}
-	glog.Infof("Watching file %s", path)
+	glog.V(1).Infof("Watching file %s", path)
 	go util.Forever(config.run, period)
 	return config
 }

pkg/kubelet/config/http.go

@@ -44,7 +44,7 @@ func NewSourceURL(url string, period time.Duration, updates chan<- interface{})
 		updates: updates,
 		data:    nil,
 	}
-	glog.Infof("Watching URL %s", url)
+	glog.V(1).Infof("Watching URL %s", url)
 	go util.Forever(config.run, period)
 	return config
 }

pkg/kubelet/dockertools/docker.go

@@ -75,11 +75,11 @@ func NewDockerPuller(client DockerInterface) DockerPuller {
 	if err == nil {
 		cfg.addToKeyring(dp.keyring)
 	} else {
-		glog.Errorf("Unable to parse docker config file: %v", err)
+		glog.Errorf("Unable to parse Docker config file: %v", err)
 	}
 
 	if dp.keyring.count() == 0 {
-		glog.Infof("Continuing with empty docker keyring")
+		glog.V(1).Infof("Continuing with empty Docker keyring")
 	}
 
 	return dp
@@ -348,7 +348,7 @@ func ParseDockerName(name string) (podFullName, uuid, containerName string, hash
 			var err error
 			hash, err = strconv.ParseUint(pieces[1], 16, 32)
 			if err != nil {
-				glog.Infof("invalid container hash: %s", pieces[1])
+				glog.Warningf("invalid container hash: %s", pieces[1])
 			}
 		}
 	}

pkg/kubelet/kubelet.go

@@ -220,7 +220,7 @@ func makePortsAndBindings(container *api.Container) (map[docker.Port]struct{}, m
 		case "TCP":
 			protocol = "/tcp"
 		default:
-			glog.Infof("Unknown protocol '%s': defaulting to TCP", port.Protocol)
+			glog.Warningf("Unknown protocol '%s': defaulting to TCP", port.Protocol)
 			protocol = "/tcp"
 		}
 		dockerPort := docker.Port(strconv.Itoa(interiorPort) + protocol)
@@ -345,7 +345,7 @@ func (kl *Kubelet) killContainer(dockerContainer *docker.APIContainers) error {
 }
 
 func (kl *Kubelet) killContainerByID(ID, name string) error {
-	glog.Infof("Killing: %s", ID)
+	glog.V(2).Infof("Killing: %s", ID)
 	err := kl.dockerClient.StopContainer(ID, 10)
 	if len(name) == 0 {
 		return err
@@ -425,7 +425,7 @@ func (kl *Kubelet) syncPod(pod *Pod, dockerContainers dockertools.DockerContaine
 	if networkDockerContainer, found, _ := dockerContainers.FindPodContainer(podFullName, uuid, networkContainerName); found {
 		netID = dockertools.DockerID(networkDockerContainer.ID)
 	} else {
-		glog.Infof("Network container doesn't exist, creating")
+		glog.V(3).Infof("Network container doesn't exist, creating")
 		count, err := kl.deleteAllContainers(pod, podFullName, dockerContainers)
 		if err != nil {
 			return err
@@ -468,7 +468,7 @@ func (kl *Kubelet) syncPod(pod *Pod, dockerContainers dockertools.DockerContaine
 		expectedHash := dockertools.HashContainer(&container)
 		if dockerContainer, found, hash := dockerContainers.FindPodContainer(podFullName, uuid, container.Name); found {
 			containerID := dockertools.DockerID(dockerContainer.ID)
-			glog.V(1).Infof("pod %s container %s exists as %v", podFullName, container.Name, containerID)
+			glog.V(3).Infof("pod %s container %s exists as %v", podFullName, container.Name, containerID)
 
 			// look for changes in the container.
 			if hash == 0 || hash == expectedHash {
@@ -485,7 +485,7 @@ func (kl *Kubelet) syncPod(pod *Pod, dockerContainers dockertools.DockerContaine
 				}
 				glog.V(1).Infof("pod %s container %s is unhealthy.", podFullName, container.Name, healthy)
 			} else {
-				glog.V(1).Infof("container hash changed %d vs %d.", hash, expectedHash)
+				glog.V(3).Infof("container hash changed %d vs %d.", hash, expectedHash)
 			}
 			if err := kl.killContainer(dockerContainer); err != nil {
 				glog.V(1).Infof("Failed to kill container %s: %v", dockerContainer.ID, err)
@@ -503,21 +503,21 @@ func (kl *Kubelet) syncPod(pod *Pod, dockerContainers dockertools.DockerContaine
 
 		if len(recentContainers) > 0 && pod.Manifest.RestartPolicy.Always == nil {
 			if pod.Manifest.RestartPolicy.Never != nil {
-				glog.Infof("Already ran container with name %s--%s--%s, do nothing",
+				glog.V(3).Infof("Already ran container with name %s--%s--%s, do nothing",
 					podFullName, uuid, container.Name)
 				continue
 			}
 			if pod.Manifest.RestartPolicy.OnFailure != nil {
 				// Check the exit code of last run
 				if recentContainers[0].State.ExitCode == 0 {
-					glog.Infof("Already successfully ran container with name %s--%s--%s, do nothing",
+					glog.V(3).Infof("Already successfully ran container with name %s--%s--%s, do nothing",
 						podFullName, uuid, container.Name)
 					continue
 				}
 			}
 		}
 
-		glog.Infof("Container with name %s--%s--%s doesn't exist, creating %#v", podFullName, uuid, container.Name, container)
+		glog.V(3).Infof("Container with name %s--%s--%s doesn't exist, creating %#v", podFullName, uuid, container.Name, container)
 		if err := kl.dockerPuller.Pull(container.Image); err != nil {
 			glog.Errorf("Failed to pull image %s: %v skipping pod %s container %s.", container.Image, err, podFullName, container.Name)
 			continue
@@ -579,11 +579,11 @@ func (kl *Kubelet) reconcileVolumes(pods []Pod) error {
 		if _, ok := desiredVolumes[name]; !ok {
 			//TODO (jonesdl) We should somehow differentiate between volumes that are supposed
 			//to be deleted and volumes that are leftover after a crash.
-			glog.Infof("Orphaned volume %s found, tearing down volume", name)
+			glog.Warningf("Orphaned volume %s found, tearing down volume", name)
 			//TODO (jonesdl) This should not block other kubelet synchronization procedures
 			err := vol.TearDown()
 			if err != nil {
-				glog.Infof("Could not tear down volume %s (%s)", name, err)
+				glog.Errorf("Could not tear down volume %s (%s)", name, err)
 			}
 		}
 	}
@@ -592,7 +592,7 @@ func (kl *Kubelet) reconcileVolumes(pods []Pod) error {
 
 // SyncPods synchronizes the configured list of pods (desired state) with the host current state.
 func (kl *Kubelet) SyncPods(pods []Pod) error {
-	glog.Infof("Desired [%s]: %+v", kl.hostname, pods)
+	glog.V(4).Infof("Desired [%s]: %+v", kl.hostname, pods)
 	var err error
 	desiredContainers := make(map[podContainer]empty)
 
@@ -675,13 +675,13 @@ func (kl *Kubelet) syncLoop(updates <-chan PodUpdate, handler SyncHandler) {
 		case u := <-updates:
 			switch u.Op {
 			case SET:
-				glog.Infof("Containers changed [%s]", kl.hostname)
+				glog.V(3).Infof("Containers changed [%s]", kl.hostname)
 				pods = u.Pods
 				pods = filterHostPortConflicts(pods)
 
 			case UPDATE:
 				//TODO: implement updates of containers
-				glog.Infof("Containers updated, not implemented [%s]", kl.hostname)
+				glog.Warningf("Containers updated, not implemented [%s]", kl.hostname)
 				continue
 
 			default:

pkg/kubelet/server.go

@@ -48,7 +48,7 @@ type Server struct {
 
 // ListenAndServeKubeletServer initializes a server to respond to HTTP network requests on the Kubelet.
 func ListenAndServeKubeletServer(host HostInterface, updates chan<- interface{}, address string, port uint) {
-	glog.Infof("Starting to listen on %s:%d", address, port)
+	glog.V(1).Infof("Starting to listen on %s:%d", address, port)
 	handler := NewServer(host, updates)
 	s := &http.Server{
 		Addr:           net.JoinHostPort(address, strconv.FormatUint(uint64(port), 10)),

pkg/proxy/config/api.go

@@ -101,7 +101,7 @@ func handleServicesWatch(resourceVersion *uint64, ch <-chan watch.Event, updates
 		select {
 		case event, ok := <-ch:
 			if !ok {
-				glog.V(2).Infof("WatchServices channel closed")
+				glog.V(4).Infof("WatchServices channel closed")
 				return
 			}
 
@@ -150,7 +150,7 @@ func handleEndpointsWatch(resourceVersion *uint64, ch <-chan watch.Event, update
 		select {
 		case event, ok := <-ch:
 			if !ok {
-				glog.V(2).Infof("WatchEndpoints channel closed")
+				glog.V(4).Infof("WatchEndpoints channel closed")
 				return
 			}