Introduce some default log verbosity control

Move a lot of common error logging into better buckets:

glog.Errorf() - Always an error
glog.Warningf() - Something unexpected, but probably not an error
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
            * 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

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
 			}
 

pkg/proxy/config/config.go

@@ -125,24 +125,24 @@ func (s *endpointsStore) Merge(source string, change interface{}) error {
 	update := change.(EndpointsUpdate)
 	switch update.Op {
 	case ADD:
-		glog.Infof("Adding new endpoint from source %s : %v", source, update.Endpoints)
+		glog.V(4).Infof("Adding new endpoint from source %s : %v", source, update.Endpoints)
 		for _, value := range update.Endpoints {
 			endpoints[value.ID] = value
 		}
 	case REMOVE:
-		glog.Infof("Removing an endpoint %v", update)
+		glog.V(4).Infof("Removing an endpoint %v", update)
 		for _, value := range update.Endpoints {
 			delete(endpoints, value.ID)
 		}
 	case SET:
-		glog.Infof("Setting endpoints %v", update)
+		glog.V(4).Infof("Setting endpoints %v", update)
 		// Clear the old map entries by just creating a new map
 		endpoints = make(map[string]api.Endpoints)
 		for _, value := range update.Endpoints {
 			endpoints[value.ID] = value
 		}
 	default:
-		glog.Infof("Received invalid update type: %v", update)
+		glog.V(4).Infof("Received invalid update type: %v", update)
 	}
 	s.endpoints[source] = endpoints
 	s.endpointLock.Unlock()
@@ -220,24 +220,24 @@ func (s *serviceStore) Merge(source string, change interface{}) error {
 	update := change.(ServiceUpdate)
 	switch update.Op {
 	case ADD:
-		glog.Infof("Adding new service from source %s : %v", source, update.Services)
+		glog.V(4).Infof("Adding new service from source %s : %v", source, update.Services)
 		for _, value := range update.Services {
 			services[value.ID] = value
 		}
 	case REMOVE:
-		glog.Infof("Removing a service %v", update)
+		glog.V(4).Infof("Removing a service %v", update)
 		for _, value := range update.Services {
 			delete(services, value.ID)
 		}
 	case SET:
-		glog.Infof("Setting services %v", update)
+		glog.V(4).Infof("Setting services %v", update)
 		// Clear the old map entries by just creating a new map
 		services = make(map[string]api.Service)
 		for _, value := range update.Services {
 			services[value.ID] = value
 		}
 	default:
-		glog.Infof("Received invalid update type: %v", update)
+		glog.V(4).Infof("Received invalid update type: %v", update)
 	}
 	s.services[source] = services
 	s.serviceLock.Unlock()

pkg/proxy/config/etcd.go

@@ -121,7 +121,7 @@ func (s ConfigSourceEtcd) GetServices() ([]api.Service, []api.Endpoints, error)
 	response, err := s.client.Get(registryRoot+"/specs", true, false)
 	if err != nil {
 		if tools.IsEtcdNotFound(err) {
-			glog.V(1).Infof("Failed to get the key %s: %v", registryRoot, err)
+			glog.V(4).Infof("Failed to get the key %s: %v", registryRoot, err)
 		} else {
 			glog.Errorf("Failed to contact etcd for key %s: %v", registryRoot, err)
 		}
@@ -144,12 +144,12 @@ func (s ConfigSourceEtcd) GetServices() ([]api.Service, []api.Endpoints, error)
 			endpoints, err := s.GetEndpoints(svc.ID)
 			if err != nil {
 				if tools.IsEtcdNotFound(err) {
-					glog.V(1).Infof("Unable to get endpoints for %s : %v", svc.ID, err)
+					glog.V(4).Infof("Unable to get endpoints for %s : %v", svc.ID, err)
 				}
 				glog.Errorf("Couldn't get endpoints for %s : %v skipping", svc.ID, err)
 				endpoints = api.Endpoints{}
 			} else {
-				glog.Infof("Got service: %s on localport %d mapping to: %s", svc.ID, svc.Port, endpoints)
+				glog.V(3).Infof("Got service: %s on localport %d mapping to: %s", svc.ID, svc.Port, endpoints)
 			}
 			retEndpoints[i] = endpoints
 		}
@@ -186,7 +186,7 @@ func etcdResponseToService(response *etcd.Response) (*api.Service, error) {
 }
 
 func (s ConfigSourceEtcd) WatchForChanges() {
-	glog.Info("Setting up a watch for new services")
+	glog.V(4).Info("Setting up a watch for new services")
 	watchChannel := make(chan *etcd.Response)
 	go s.client.Watch("/registry/services/", 0, true, watchChannel, nil)
 	for {
@@ -199,7 +199,7 @@ func (s ConfigSourceEtcd) WatchForChanges() {
 }
 
 func (s ConfigSourceEtcd) ProcessChange(response *etcd.Response) {
-	glog.Infof("Processing a change in service configuration... %s", *response)
+	glog.V(4).Infof("Processing a change in service configuration... %s", *response)
 
 	// If it's a new service being added (signified by a localport being added)
 	// then process it as such
@@ -212,7 +212,7 @@ func (s ConfigSourceEtcd) ProcessChange(response *etcd.Response) {
 			return
 		}
 
-		glog.Infof("New service added/updated: %#v", service)
+		glog.V(4).Infof("New service added/updated: %#v", service)
 		serviceUpdate := ServiceUpdate{Op: ADD, Services: []api.Service{*service}}
 		s.serviceChannel <- serviceUpdate
 		return
@@ -220,17 +220,17 @@ func (s ConfigSourceEtcd) ProcessChange(response *etcd.Response) {
 	if response.Action == "delete" {
 		parts := strings.Split(response.Node.Key[1:], "/")
 		if len(parts) == 4 {
-			glog.Infof("Deleting service: %s", parts[3])
+			glog.V(4).Infof("Deleting service: %s", parts[3])
 			serviceUpdate := ServiceUpdate{Op: REMOVE, Services: []api.Service{{JSONBase: api.JSONBase{ID: parts[3]}}}}
 			s.serviceChannel <- serviceUpdate
 			return
 		}
-		glog.Infof("Unknown service delete: %#v", parts)
+		glog.Warningf("Unknown service delete: %#v", parts)
 	}
 }
 
 func (s ConfigSourceEtcd) ProcessEndpointResponse(response *etcd.Response) {
-	glog.Infof("Processing a change in endpoint configuration... %s", *response)
+	glog.V(4).Infof("Processing a change in endpoint configuration... %s", *response)
 	var endpoints api.Endpoints
 	err := latest.Codec.DecodeInto([]byte(response.Node.Value), &endpoints)
 	if err != nil {

pkg/proxy/config/file.go

@@ -72,7 +72,7 @@ func NewConfigSourceFile(filename string, serviceChannel chan ServiceUpdate, end
 
 // Run begins watching the config file.
 func (s ConfigSourceFile) Run() {
-	glog.Infof("Watching file %s", s.filename)
+	glog.V(1).Infof("Watching file %s", s.filename)
 	var lastData []byte
 	var lastServices []api.Service
 	var lastEndpoints []api.Endpoints

pkg/proxy/proxier.go

@@ -90,14 +90,14 @@ func (tcp *tcpProxySocket) ProxyLoop(service string, proxier *Proxier) {
 			glog.Errorf("Accept failed: %v", err)
 			continue
 		}
-		glog.Infof("Accepted TCP connection from %v to %v", inConn.RemoteAddr(), inConn.LocalAddr())
+		glog.V(2).Infof("Accepted TCP connection from %v to %v", inConn.RemoteAddr(), inConn.LocalAddr())
 		endpoint, err := proxier.loadBalancer.NextEndpoint(service, inConn.RemoteAddr())
 		if err != nil {
 			glog.Errorf("Couldn't find an endpoint for %s %v", service, err)
 			inConn.Close()
 			continue
 		}
-		glog.Infof("Mapped service %s to endpoint %s", service, endpoint)
+		glog.V(3).Infof("Mapped service %s to endpoint %s", service, endpoint)
 		// TODO: This could spin up a new goroutine to make the outbound connection,
 		// and keep accepting inbound traffic.
 		outConn, err := net.DialTimeout("tcp", endpoint, endpointDialTimeout)
@@ -116,7 +116,7 @@ func (tcp *tcpProxySocket) ProxyLoop(service string, proxier *Proxier) {
 func proxyTCP(in, out *net.TCPConn) {
 	var wg sync.WaitGroup
 	wg.Add(2)
-	glog.Infof("Creating proxy between %v <-> %v <-> %v <-> %v",
+	glog.V(4).Infof("Creating proxy between %v <-> %v <-> %v <-> %v",
 		in.RemoteAddr(), in.LocalAddr(), out.LocalAddr(), out.RemoteAddr())
 	go copyBytes(in, out, &wg)
 	go copyBytes(out, in, &wg)
@@ -127,7 +127,7 @@ func proxyTCP(in, out *net.TCPConn) {
 
 func copyBytes(in, out *net.TCPConn, wg *sync.WaitGroup) {
 	defer wg.Done()
-	glog.Infof("Copying from %v <-> %v <-> %v <-> %v",
+	glog.V(4).Infof("Copying from %v <-> %v <-> %v <-> %v",
 		in.RemoteAddr(), in.LocalAddr(), out.LocalAddr(), out.RemoteAddr())
 	if _, err := io.Copy(in, out); err != nil {
 		glog.Errorf("I/O error: %v", err)
@@ -176,7 +176,7 @@ func (udp *udpProxySocket) ProxyLoop(service string, proxier *Proxier) {
 		if err != nil {
 			if e, ok := err.(net.Error); ok {
 				if e.Temporary() {
-					glog.Infof("ReadFrom had a temporary failure: %v", err)
+					glog.V(1).Infof("ReadFrom had a temporary failure: %v", err)
 					continue
 				}
 			}
@@ -214,13 +214,13 @@ func (udp *udpProxySocket) getBackendConn(activeClients *clientCache, cliAddr ne
 	if !found {
 		// TODO: This could spin up a new goroutine to make the outbound connection,
 		// and keep accepting inbound traffic.
-		glog.Infof("New UDP connection from %s", cliAddr)
+		glog.V(2).Infof("New UDP connection from %s", cliAddr)
 		endpoint, err := proxier.loadBalancer.NextEndpoint(service, cliAddr)
 		if err != nil {
 			glog.Errorf("Couldn't find an endpoint for %s %v", service, err)
 			return nil, err
 		}
-		glog.Infof("Mapped service %s to endpoint %s", service, endpoint)
+		glog.V(4).Infof("Mapped service %s to endpoint %s", service, endpoint)
 		svrConn, err = net.DialTimeout("udp", endpoint, endpointDialTimeout)
 		if err != nil {
 			// TODO: Try another endpoint?
@@ -269,7 +269,7 @@ func (udp *udpProxySocket) proxyClient(cliAddr net.Addr, svrConn net.Conn, activ
 func logTimeout(err error) bool {
 	if e, ok := err.(net.Error); ok {
 		if e.Timeout() {
-			glog.Infof("connection to endpoint closed due to inactivity")
+			glog.V(1).Infof("connection to endpoint closed due to inactivity")
 			return true
 		}
 	}
@@ -329,7 +329,7 @@ func (proxier *Proxier) stopProxyInternal(service string, info *serviceInfo) err
 	if !info.setActive(false) {
 		return nil
 	}
-	glog.Infof("Removing service: %s", service)
+	glog.V(3).Infof("Removing service: %s", service)
 	delete(proxier.serviceMap, service)
 	return info.socket.Close()
 }
@@ -375,7 +375,7 @@ func (proxier *Proxier) addServiceOnUnusedPort(service, protocol string, timeout
 }
 
 func (proxier *Proxier) startAccepting(service string, sock proxySocket) {
-	glog.Infof("Listening for %s on %s:%s", service, sock.Addr().Network(), sock.Addr().String())
+	glog.V(1).Infof("Listening for %s on %s:%s", service, sock.Addr().Network(), sock.Addr().String())
 	go func(service string, proxier *Proxier) {
 		defer util.HandleCrash()
 		sock.ProxyLoop(service, proxier)
@@ -389,7 +389,7 @@ const udpIdleTimeout = 1 * time.Minute
 // Active service proxies are reinitialized if found in the update set or
 // shutdown if missing from the update set.
 func (proxier *Proxier) OnUpdate(services []api.Service) {
-	glog.Infof("Received update notice: %+v", services)
+	glog.V(4).Infof("Received update notice: %+v", services)
 	activeServices := util.StringSet{}
 	for _, service := range services {
 		activeServices.Insert(service.ID)
@@ -404,7 +404,7 @@ func (proxier *Proxier) OnUpdate(services []api.Service) {
 				glog.Errorf("error stopping %s: %v", service.ID, err)
 			}
 		}
-		glog.Infof("Adding a new service %s on %s port %d", service.ID, service.Protocol, service.Port)
+		glog.V(3).Infof("Adding a new service %s on %s port %d", service.ID, service.Protocol, service.Port)
 		sock, err := newProxySocket(service.Protocol, proxier.address, service.Port)
 		if err != nil {
 			glog.Errorf("Failed to get a socket for %s: %+v", service.ID, err)

pkg/proxy/roundrobin.go

@@ -101,7 +101,7 @@ func (lb *LoadBalancerRR) OnUpdate(endpoints []api.Endpoints) {
 		existingEndpoints, exists := lb.endpointsMap[endpoint.ID]
 		validEndpoints := filterValidEndpoints(endpoint.Endpoints)
 		if !exists || !reflect.DeepEqual(existingEndpoints, validEndpoints) {
-			glog.Infof("LoadBalancerRR: Setting endpoints for %s to %+v", endpoint.ID, endpoint.Endpoints)
+			glog.V(3).Infof("LoadBalancerRR: Setting endpoints for %s to %+v", endpoint.ID, endpoint.Endpoints)
 			lb.endpointsMap[endpoint.ID] = validEndpoints
 			// Reset the round-robin index.
 			lb.rrIndex[endpoint.ID] = 0
@@ -111,7 +111,7 @@ func (lb *LoadBalancerRR) OnUpdate(endpoints []api.Endpoints) {
 	// Remove endpoints missing from the update.
 	for k, v := range lb.endpointsMap {
 		if _, exists := registeredEndpoints[k]; !exists {
-			glog.Infof("LoadBalancerRR: Removing endpoints for %s -> %+v", k, v)
+			glog.V(3).Infof("LoadBalancerRR: Removing endpoints for %s -> %+v", k, v)
 			delete(lb.endpointsMap, k)
 		}
 	}