implements structured logging for apiserver

cmd/apiserver/main.go

@@ -3,16 +3,17 @@ package main
 import (
 	goflag "flag"
 	"fmt"
-	"log"
 	"os"
 
-	"github.com/golang/glog"
+	kitLog "github.com/go-kit/kit/log"
+	"github.com/go-stack/stack"
 	"github.com/spf13/pflag"
 
 	apipkg "github.com/sapcc/kubernikus/pkg/api"
 	"github.com/sapcc/kubernikus/pkg/api/rest"
 	"github.com/sapcc/kubernikus/pkg/api/rest/operations"
 	"github.com/sapcc/kubernikus/pkg/api/spec"
+	logutil "github.com/sapcc/kubernikus/pkg/util/log"
 	"github.com/sapcc/kubernikus/pkg/version"
 )
 
@@ -23,10 +24,17 @@ func init() {
 }
 
 func main() {
+	var logger kitLog.Logger
+	logger = kitLog.NewLogfmtLogger(kitLog.NewSyncWriter(os.Stderr))
+	logger = logutil.NewTrailingNilFilter(logger)
+	logger = kitLog.With(logger, "ts", kitLog.DefaultTimestampUTC, "caller", Caller(3))
 
 	swaggerSpec, err := spec.Spec()
 	if err != nil {
-		log.Fatalln(err)
+		logger.Log(
+			"msg", "failed to spec swagger spec",
+			"err", err)
+		os.Exit(1)
 	}
 
 	var server *rest.Server // make sure init is called
@@ -53,12 +61,21 @@ func main() {
 
 	api := operations.NewKubernikusAPI(swaggerSpec)
 
-	rt := &apipkg.Runtime{Namespace: namespace}
+	rt := &apipkg.Runtime{
+		Namespace: namespace,
+		Logger:    logger,
+	}
 	rt.Kubernikus, rt.Kubernetes = rest.NewKubeClients()
 	if err := rest.Configure(api, rt); err != nil {
-		glog.Fatalf("Failed to configure apiserver :%s", err)
+		logger.Log(
+			"msg", "failed to configure API server",
+			"err", err)
+		os.Exit(1)
 	}
-	glog.Infof("Starting kubernikus apiserver v%v. Using namespace %s", version.GitCommit, namespace)
+	logger.Log(
+		"msg", "starting Kubernikus API",
+		"namespace", namespace,
+		"version", version.GitCommit)
 
 	// get server with flag values filled out
 	server = rest.NewServer(api)
@@ -67,7 +84,14 @@ func main() {
 
 	server.ConfigureAPI()
 	if err := server.Serve(); err != nil {
-		log.Fatalln(err)
+		logger.Log(
+			"msg", "failed to start API server",
+			"err", err)
+		os.Exit(1)
 	}
 
 }
+
+func Caller(depth int) kitLog.Valuer {
+	return func() interface{} { return fmt.Sprintf("%+v", stack.Caller(depth)) }
+}

pkg/api/handlers/get_openstack_metadata.go

@@ -6,7 +6,7 @@ import (
 	"github.com/sapcc/kubernikus/pkg/api"
 	"github.com/sapcc/kubernikus/pkg/api/models"
 	"github.com/sapcc/kubernikus/pkg/api/rest/operations"
-	"github.com/sapcc/kubernikus/pkg/client/openstack"
+	"github.com/sapcc/kubernikus/pkg/client/openstack/scoped"
 )
 
 func NewGetOpenstackMetadata(rt *api.Runtime) operations.GetOpenstackMetadataHandler {
@@ -29,7 +29,7 @@ func (d *getOpenstackMetadata) Handle(params operations.GetOpenstackMetadataPara
 		},
 	}
 
-	client, err := openstack.NewScopedClient(authOptions)
+	client, err := scoped.NewClient(authOptions, d.Logger)
 	if err != nil {
 		return NewErrorResponse(&operations.GetOpenstackMetadataDefault{}, 500, err.Error())
 	}

pkg/api/rest/api_test.go

@@ -9,6 +9,7 @@ import (
 	"strings"
 	"testing"
 
+	kitlog "github.com/go-kit/kit/log"
 	errors "github.com/go-openapi/errors"
 	"github.com/stretchr/testify/assert"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -57,6 +58,7 @@ func createTestHandler(t *testing.T) (http.Handler, *apipkg.Runtime) {
 		Namespace:  NAMESPACE,
 		Kubernikus: kubernikusfake.NewSimpleClientset(),
 		Kubernetes: fake.NewSimpleClientset(),
+		Logger:     kitlog.NewNopLogger(),
 	}
 	if err := Configure(api, rt); err != nil {
 		t.Fatal(err)

pkg/api/rest/configure.go

@@ -2,16 +2,21 @@ package rest
 
 import (
 	"fmt"
+	"net/http"
+	"strings"
 
 	"github.com/go-openapi/errors"
 	runtime "github.com/go-openapi/runtime"
-	"github.com/golang/glog"
+	"github.com/go-openapi/runtime/middleware"
+	"github.com/justinas/alice"
+	"github.com/rs/cors"
 
 	apipkg "github.com/sapcc/kubernikus/pkg/api"
 	"github.com/sapcc/kubernikus/pkg/api/auth"
 	"github.com/sapcc/kubernikus/pkg/api/handlers"
 	"github.com/sapcc/kubernikus/pkg/api/rest/operations"
 	"github.com/sapcc/kubernikus/pkg/api/spec"
+	logutil "github.com/sapcc/kubernikus/pkg/util/log"
 )
 
 func Configure(api *operations.KubernikusAPI, rt *apipkg.Runtime) error {
@@ -23,7 +28,7 @@ func Configure(api *operations.KubernikusAPI, rt *apipkg.Runtime) error {
 	//
 	// Example:
 	api.Logger = func(msg string, args ...interface{}) {
-		glog.InfoDepth(2, fmt.Sprintf(msg, args...))
+		rt.Logger.Log("msg", fmt.Sprintf(msg, args...))
 	}
 
 	api.JSONConsumer = runtime.JSONConsumer()
@@ -60,5 +65,39 @@ func Configure(api *operations.KubernikusAPI, rt *apipkg.Runtime) error {
 	api.GetClusterEventsHandler = handlers.NewGetClusterEvents(rt)
 
 	api.ServerShutdown = func() {}
+
+	api.Middleware = func(builder middleware.Builder) http.Handler {
+		return setupGlobalMiddleware(api.Context().APIHandler(builder), rt)
+	}
 	return nil
 }
+
+// The middleware configuration happens before anything, this middleware also applies to serving the swagger.json document.
+// So this is a good place to plug in a panic handling middleware, logging and metrics
+func setupGlobalMiddleware(handler http.Handler, rt *apipkg.Runtime) http.Handler {
+	corsHandler := cors.New(cors.Options{
+		AllowedHeaders: []string{"X-Auth-Token", "Content-Type", "Accept"},
+		AllowedMethods: []string{"GET", "HEAD", "POST", "DELETE", "PUT"},
+		MaxAge:         600,
+	}).Handler
+
+	loggingHandler := func(next http.Handler) http.Handler {
+		return logutil.LoggingHandler(rt.Logger, next)
+	}
+
+	redocHandler := func(next http.Handler) http.Handler {
+		return middleware.Redoc(middleware.RedocOpts{Path: "swagger"}, next)
+	}
+
+	staticHandler := func(next http.Handler) http.Handler {
+		return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
+			if strings.HasPrefix(r.URL.Path, "/docs") {
+				http.StripPrefix("/docs", http.FileServer(http.Dir("static/docs"))).ServeHTTP(rw, r)
+				return
+			}
+			next.ServeHTTP(rw, r)
+		})
+	}
+
+	return alice.New(loggingHandler, handlers.RootHandler, redocHandler, staticHandler, corsHandler).Then(handler)
+}

pkg/api/rest/configure_kubernikus.go

@@ -3,16 +3,9 @@ package rest
 import (
 	"crypto/tls"
 	"net/http"
-	"os"
-	"strings"
 
-	"github.com/go-openapi/runtime/middleware"
-	gmiddleware "github.com/gorilla/handlers"
-	"github.com/justinas/alice"
-	"github.com/rs/cors"
 	graceful "github.com/tylerb/graceful"
 
-	"github.com/sapcc/kubernikus/pkg/api/handlers"
 	"github.com/sapcc/kubernikus/pkg/api/rest/operations"
 )
 
@@ -25,8 +18,9 @@ func configureFlags(api *operations.KubernikusAPI) {
 }
 
 func configureAPI(api *operations.KubernikusAPI) http.Handler {
-
-	return setupGlobalMiddleware(api.Serve(setupMiddlewares))
+	return api.Serve(func(handler http.Handler) http.Handler {
+		return handler
+	})
 }
 
 // The TLS configuration before HTTPS server starts.
@@ -40,38 +34,3 @@ func configureTLS(tlsConfig *tls.Config) {
 // scheme value will be set accordingly: "http", "https" or "unix"
 func configureServer(s *graceful.Server, scheme, addr string) {
 }
-
-// The middleware configuration is for the handler executors. These do not apply to the swagger.json document.
-// The middleware executes after routing but before authentication, binding and validation
-func setupMiddlewares(handler http.Handler) http.Handler {
-	return handler
-}
-
-// The middleware configuration happens before anything, this middleware also applies to serving the swagger.json document.
-// So this is a good place to plug in a panic handling middleware, logging and metrics
-func setupGlobalMiddleware(handler http.Handler) http.Handler {
-	corsHandler := cors.New(cors.Options{
-		AllowedHeaders: []string{"X-Auth-Token", "Content-Type", "Accept"},
-		AllowedMethods: []string{"GET", "HEAD", "POST", "DELETE", "PUT"},
-		MaxAge:         600,
-	}).Handler
-
-	loggingHandler := func(next http.Handler) http.Handler {
-		return gmiddleware.LoggingHandler(os.Stdout, next)
-	}
-	redocHandler := func(next http.Handler) http.Handler {
-		return middleware.Redoc(middleware.RedocOpts{Path: "swagger"}, next)
-	}
-
-	return alice.New(loggingHandler, handlers.RootHandler, redocHandler, StaticFiles, corsHandler).Then(handler)
-}
-
-func StaticFiles(next http.Handler) http.Handler {
-	return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
-		if strings.HasPrefix(r.URL.Path, "/docs") {
-			http.StripPrefix("/docs", http.FileServer(http.Dir("static/docs"))).ServeHTTP(rw, r)
-			return
-		}
-		next.ServeHTTP(rw, r)
-	})
-}

pkg/api/runtime.go

@@ -1,6 +1,8 @@
 package api
 
 import (
+	"github.com/go-kit/kit/log"
+
 	"github.com/sapcc/kubernikus/pkg/generated/clientset"
 	"k8s.io/client-go/kubernetes"
 )
@@ -9,4 +11,5 @@ type Runtime struct {
 	Kubernikus clientset.Interface
 	Kubernetes kubernetes.Interface
 	Namespace  string
+	Logger     log.Logger
 }