removes glog

This commit removes all glog references in favor of the structured
logging approach using go-kit/log.

There is plenty room for improvement. The intention here is to rid glog
without introducing to many bugs.

`kubernikusctl` is left to use glog as the main intent of logging here
is human consumption on the cli without an intermediate log retrieval
system. Also, there's tight integration with k8s clients that log using
glog anyway.

The log output is not yet completely clean and 100% structured logging,
because of the informer framwork being uncooperative. We could get rid
of that using a higher default log threshold instead of the default
`INFO`. That exercise is left for another time.

This commit fixes #100

cmd/apiserver/main.go

@@ -65,7 +65,14 @@ func main() {
 		Namespace: namespace,
 		Logger:    logger,
 	}
-	rt.Kubernikus, rt.Kubernetes = rest.NewKubeClients()
+	rt.Kubernikus, rt.Kubernetes, err = rest.NewKubeClients(logger)
+	if err != nil {
+		logger.Log(
+			"msg", "failed to create kubernetes clients",
+			"err", err)
+		os.Exit(1)
+	}
+
 	if err := rest.Configure(api, rt); err != nil {
 		logger.Log(
 			"msg", "failed to configure API server",

pkg/api/auth/authorizer.go

@@ -58,7 +58,7 @@ func NewOsloPolicyAuthorizer(document *loads.Document, rules map[string]string)
 			//Add this once go-openapi/spec includes this fix: https://github.com/go-openapi/spec/pull/40
 			//secSchemes := document.Analyzer.SecurityDefinitionsFor(operation)
 			//if _, ok := rules[operation.ID]; !ok && len(secSchemes) > 0 {
-			//  glog.Errorf("No policy found for %s. The api route will not be accessible", operation.ID)
+			//  logger.Log("msg", "policy not found. The api route will not be accessible", "operation", operation.ID)
 			//}
 		}
 	}

pkg/api/handlers/create_cluster.go

@@ -3,7 +3,6 @@ package handlers
 import (
 	"github.com/go-openapi/runtime/middleware"
 	"github.com/go-openapi/validate"
-	"github.com/golang/glog"
 
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -24,6 +23,7 @@ type createCluster struct {
 }
 
 func (d *createCluster) Handle(params operations.CreateClusterParams, principal *models.Principal) middleware.Responder {
+	logger := getTracingLogger(params.HTTPRequest)
 	name := params.Body.Name
 	spec := params.Body.Spec
 
@@ -49,7 +49,12 @@ func (d *createCluster) Handle(params operations.CreateClusterParams, principal
 	k8sutil.EnsureNamespace(d.Kubernetes, d.Namespace)
 	kluster, err = d.Kubernikus.Kubernikus().Klusters(d.Namespace).Create(kluster)
 	if err != nil {
-		glog.Errorf("Failed to create cluster: %s", err)
+		logger.Log(
+			"msg", "failed to create cluster",
+			"kluster", kluster.GetName(),
+			"project", kluster.Account(),
+			"err", err)
+
 		if apierrors.IsAlreadyExists(err) {
 			return NewErrorResponse(&operations.CreateClusterDefault{}, 409, "Cluster with name %s already exists", name)
 		}

pkg/api/rest/kubeclient.go

@@ -1,7 +1,9 @@
 package rest
 
 import (
-	"github.com/golang/glog"
+	"fmt"
+
+	kitlog "github.com/go-kit/kit/log"
 	"github.com/spf13/pflag"
 	apiextensionsclient "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset"
 	kubernetes_clientset "k8s.io/client-go/kubernetes"
@@ -19,30 +21,30 @@ func init() {
 	pflag.StringVar(&context, "context", "", "Override context")
 }
 
-func NewKubeClients() (kubernikus_clientset.Interface, kubernetes_clientset.Interface) {
+func NewKubeClients(logger kitlog.Logger) (kubernikus_clientset.Interface, kubernetes_clientset.Interface, error) {
 	client, err := kubernikus.NewClient(kubeconfig, context)
 
 	if err != nil {
-		glog.Fatal("Failed to create kubernikus clients: %s", err)
+		return nil, nil, fmt.Errorf("Failed to create kubernikus clients: %s", err)
 	}
 
-	kubernetesClient, err := kubernetes.NewClient(kubeconfig, context)
+	kubernetesClient, err := kubernetes.NewClient(kubeconfig, context, logger)
 	if err != nil {
-		glog.Fatal("Failed to create kubernetes clients: %s", err)
+		return nil, nil, fmt.Errorf("Failed to create kubernetes clients: %s", err)
 	}
 
 	config, err := kubernetes.NewConfig(kubeconfig, context)
 	if err != nil {
-		glog.Fatalf("Failed to create kubernetes config: %s", err)
+		return nil, nil, fmt.Errorf("Failed to create kubernetes config: %s", err)
 	}
 	apiextensionsclientset, err := apiextensionsclient.NewForConfig(config)
 	if err != nil {
-		glog.Fatal("Failed to create apiextenstionsclient: %s", err)
+		return nil, nil, fmt.Errorf("Failed to create apiextenstionsclient: %s", err)
 	}
 
-	if err := kubernetes.EnsureCRD(apiextensionsclientset); err != nil {
-		glog.Fatalf("Couldn't create CRD: %s", err)
+	if err := kubernetes.EnsureCRD(apiextensionsclientset, logger); err != nil {
+		return nil, nil, fmt.Errorf("Couldn't create CRD: %s", err)
 	}
 
-	return client, kubernetesClient
+	return client, kubernetesClient, nil
 }

pkg/client/helm/client.go

@@ -5,15 +5,16 @@ import (
 	"os"
 	"runtime"
 
-	"github.com/golang/glog"
+	"github.com/go-kit/kit/log"
 	"k8s.io/client-go/kubernetes"
 	"k8s.io/client-go/rest"
 	"k8s.io/helm/pkg/helm"
 
 	"github.com/sapcc/kubernikus/pkg/client/helm/portforwarder"
 )
 
-func NewClient(kubeClient kubernetes.Interface, kubeConfig *rest.Config) (*helm.Client, error) {
+func NewClient(kubeClient kubernetes.Interface, kubeConfig *rest.Config, logger log.Logger) (*helm.Client, error) {
+	logger = log.With(logger, "client", "helm")
 
 	tillerHost := os.Getenv("TILLER_DEPLOY_SERVICE_HOST")
 	if tillerHost == "" {
@@ -26,7 +27,9 @@ func NewClient(kubeClient kubernetes.Interface, kubeConfig *rest.Config) (*helm.
 	tillerHost = fmt.Sprintf("%s:%s", tillerHost, tillerPort)
 
 	if _, err := rest.InClusterConfig(); err != nil {
-		glog.V(2).Info("We are not running inside the cluster. Creating tunnel to tiller pod.")
+		logger.Log(
+			"msg", "We are not running inside the cluster. Creating tunnel to tiller pod.",
+			"v", 2)
 		tunnel, err := portforwarder.New("kube-system", kubeClient, kubeConfig)
 		if err != nil {
 			return nil, err
@@ -35,7 +38,10 @@ func NewClient(kubeClient kubernetes.Interface, kubeConfig *rest.Config) (*helm.
 		client := helm.NewClient(helm.Host(tillerHost))
 		//Lets see how this goes: We close the tunnel as soon as the client is GC'ed.
 		runtime.SetFinalizer(client, func(_ *helm.Client) {
-			glog.V(2).Info("Tearing Down tunnel to tiller at %s", tillerHost)
+			logger.Log(
+				"msg", "trearing down tunnel to tiller",
+				"host", tillerHost,
+				"v", 2)
 			tunnel.Close()
 		})
 		return client, nil

pkg/client/kubernetes/client.go

@@ -8,7 +8,7 @@ import (
 	"sync"
 	"time"
 
-	"github.com/golang/glog"
+	kitlog "github.com/go-kit/kit/log"
 	apiextensionsv1beta1 "k8s.io/apiextensions-apiserver/pkg/apis/apiextensions/v1beta1"
 	apiextensionsclient "k8s.io/apiextensions-apiserver/pkg/client/clientset/clientset"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
@@ -28,20 +28,27 @@ import (
 type SharedClientFactory struct {
 	clients          *sync.Map
 	secretsInterface typedv1.SecretInterface
+	Logger           kitlog.Logger
 }
 
-func NewSharedClientFactory(secrets typedv1.SecretInterface, klusterEvents cache.SharedIndexInformer) *SharedClientFactory {
+func NewSharedClientFactory(secrets typedv1.SecretInterface, klusterEvents cache.SharedIndexInformer, logger kitlog.Logger) *SharedClientFactory {
 	factory := &SharedClientFactory{
 		clients:          new(sync.Map),
 		secretsInterface: secrets,
+		Logger:           kitlog.With(logger, "client", "kubernetes"),
 	}
 
 	if klusterEvents != nil {
 		klusterEvents.AddEventHandler(cache.ResourceEventHandlerFuncs{
 			DeleteFunc: func(obj interface{}) {
 				if kluster, ok := obj.(*kubernikus_v1.Kluster); ok {
-					glog.V(5).Infof("Deleting shared kubernetes client for kluster %s", kluster.GetName())
 					factory.clients.Delete(kluster.GetUID())
+					factory.Logger.Log(
+						"msg", "deleted shared kubernetes client",
+						"kluster", kluster.GetName(),
+						"project", kluster.Account(),
+						"v", 2,
+					)
 				}
 			},
 		})
@@ -50,11 +57,20 @@ func NewSharedClientFactory(secrets typedv1.SecretInterface, klusterEvents cache
 	return factory
 }
 
-func (f *SharedClientFactory) ClientFor(k *kubernikus_v1.Kluster) (kubernetes.Interface, error) {
+func (f *SharedClientFactory) ClientFor(k *kubernikus_v1.Kluster) (clientset kubernetes.Interface, err error) {
+	defer func() {
+		f.Logger.Log(
+			"msg", "created shared kubernetes client",
+			"kluster", k.GetName(),
+			"project", k.Account(),
+			"v", 2,
+			"err", err,
+		)
+	}()
+
 	if client, found := f.clients.Load(k.GetUID()); found {
 		return client.(kubernetes.Interface), nil
 	}
-	glog.V(5).Info("Creating new shared kubernetes client for kluster %s", k.GetName())
 	secret, err := f.secretsInterface.Get(k.GetName(), metav1.GetOptions{})
 	if err != nil {
 		return nil, err
@@ -81,7 +97,7 @@ func (f *SharedClientFactory) ClientFor(k *kubernikus_v1.Kluster) (kubernetes.In
 		},
 	}
 
-	clientset, err := kubernetes.NewForConfig(&c)
+	clientset, err = kubernetes.NewForConfig(&c)
 	if err != nil {
 		return nil, err
 	}
@@ -103,15 +119,10 @@ func NewConfig(kubeconfig, context string) (*rest.Config, error) {
 		rules.ExplicitPath = kubeconfig
 	}
 
-	config, err := clientcmd.NewNonInteractiveDeferredLoadingClientConfig(rules, overrides).ClientConfig()
-	if err != nil {
-		glog.Fatalf("Couldn't get Kubernetes default config: %s", err)
-	}
-
-	return config, nil
+	return clientcmd.NewNonInteractiveDeferredLoadingClientConfig(rules, overrides).ClientConfig()
 }
 
-func NewClient(kubeconfig, context string) (kubernetes.Interface, error) {
+func NewClient(kubeconfig, context string, logger kitlog.Logger) (kubernetes.Interface, error) {
 	config, err := NewConfig(kubeconfig, context)
 	if err != nil {
 		return nil, err
@@ -122,7 +133,11 @@ func NewClient(kubeconfig, context string) (kubernetes.Interface, error) {
 		return nil, err
 	}
 
-	glog.V(3).Infof("Using Kubernetes Api at %s", config.Host)
+	logger.Log(
+		"msg", "created new kubernetes client",
+		"host", config.Host,
+		"v", 3,
+	)
 
 	return clientset, nil
 }
@@ -162,7 +177,7 @@ func NewClientConfigV1(name, user, url string, key, cert, ca []byte) clientcmdap
 	}
 }
 
-func EnsureCRD(clientset apiextensionsclient.Interface) error {
+func EnsureCRD(clientset apiextensionsclient.Interface, logger kitlog.Logger) error {
 	klusterCRDName := kubernikus_v1.KlusterResourcePlural + "." + kubernikus_v1.GroupName
 	crd := &apiextensionsv1beta1.CustomResourceDefinition{
 		ObjectMeta: metav1.ObjectMeta{
@@ -197,7 +212,10 @@ func EnsureCRD(clientset apiextensionsclient.Interface) error {
 				}
 			case apiextensionsv1beta1.NamesAccepted:
 				if cond.Status == apiextensionsv1beta1.ConditionFalse {
-					glog.Errorf("Name conflict: %v\n", cond.Reason)
+					logger.Log(
+						"msg", "name conflict while ensuring CRD",
+						"reason", cond.Reason,
+					)
 				}
 			}
 		}
@@ -213,14 +231,16 @@ func EnsureCRD(clientset apiextensionsclient.Interface) error {
 	return nil
 }
 
-func WaitForServer(client kubernetes.Interface, stopCh <-chan struct{}) error {
+func WaitForServer(client kubernetes.Interface, stopCh <-chan struct{}, logger kitlog.Logger) error {
 	var healthzContent string
 
 	err := wait.PollUntil(time.Second, func() (bool, error) {
 		healthStatus := 0
 		resp := client.Discovery().RESTClient().Get().AbsPath("/healthz").Do().StatusCode(&healthStatus)
 		if healthStatus != http.StatusOK {
-			glog.Errorf("Server isn't healthy yet.  Waiting a little while.")
+			logger.Log(
+				"msg", "server isn't health yet. Waiting a little while.",
+			)
 			return false, nil
 		}
 		content, _ := resp.Raw()