Refacter API server emphasis on logging

* To aid in debugging log API request and response bodies at trace
  level. Events can be correlated using the X-Reference-Id.
* Server now echos X-Reference-Id from client if set, otherwise
  generates an unique id.
* Move logic for X-Reference-Id into middleware
* Change uses of Header.Add() to Set() when setting Content-Type
* Log API operations in Apache format using gorilla middleware
* Port server code to use BaseContext and ConnContext

Fixes #10053

Signed-off-by: Jhon Honce <jhonce@redhat.com>

6 files changed, 172 insertions, 73 deletions

diff --git a/pkg/api/server/handler_api.go b/pkg/api/server/handler_api.go
index becc674c0..88b9b7397 100644
--- a/pkg/api/server/handler_api.go
+++ b/pkg/api/server/handler_api.go
@@ -1,61 +1,25 @@
 package server
 
 import (
-	"context"
 	"fmt"
 	"net/http"
 	"runtime"
 
-	"github.com/containers/podman/v3/pkg/api/handlers/utils"
-	"github.com/containers/podman/v3/pkg/auth"
 	"github.com/containers/podman/v3/version"
-	"github.com/google/uuid"
 	"github.com/sirupsen/logrus"
 )
 
 // APIHandler is a wrapper to enhance HandlerFunc's and remove redundant code
 func (s *APIServer) APIHandler(h http.HandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
-		// http.Server hides panics, we want to see them and fix the cause.
-		defer func() {
-			err := recover()
-			if err != nil {
-				buf := make([]byte, 1<<20)
-				n := runtime.Stack(buf, true)
-				logrus.Warnf("Recovering from API handler panic: %v, %s", err, buf[:n])
-				// Try to inform client things went south... won't work if handler already started writing response body
-				utils.InternalServerError(w, fmt.Errorf("%v", err))
-			}
-		}()
-
-		// Wrapper to hide some boiler plate
+		// Wrapper to hide some boilerplate
 		fn := func(w http.ResponseWriter, r *http.Request) {
-			rid := uuid.New().String()
-			logrus.Infof("APIHandler(%s) -- %s %s BEGIN", rid, r.Method, r.URL.String())
-			if logrus.IsLevelEnabled(logrus.DebugLevel) {
-				for k, v := range r.Header {
-					switch auth.HeaderAuthName(k) {
-					case auth.XRegistryConfigHeader, auth.XRegistryAuthHeader:
-						logrus.Debugf("APIHandler(%s) -- Header: %s=<hidden>", rid, k)
-					default:
-						logrus.Debugf("APIHandler(%s) -- Header: %s=%v", rid, k, v)
-					}
-				}
-			}
-			// Set in case handler wishes to correlate logging events
-			r.Header.Set("X-Reference-Id", rid)
-
 			if err := r.ParseForm(); err != nil {
-				logrus.Infof("Failed Request: unable to parse form: %q (%s)", err, rid)
+				logrus.WithFields(logrus.Fields{
+					"X-Reference-Id": r.Header.Get("X-Reference-Id"),
+				}).Info("Failed Request: unable to parse form: " + err.Error())
 			}
 
-			// TODO: Use r.ConnContext when ported to go 1.13
-			c := context.WithValue(r.Context(), "decoder", s.Decoder) // nolint
-			c = context.WithValue(c, "runtime", s.Runtime)            // nolint
-			c = context.WithValue(c, "shutdownFunc", s.Shutdown)      // nolint
-			c = context.WithValue(c, "idletracker", s.idleTracker)    // nolint
-			r = r.WithContext(c)
-
 			cv := version.APIVersion[version.Compat][version.CurrentAPI]
 			w.Header().Set("API-Version", fmt.Sprintf("%d.%d", cv.Major, cv.Minor))
 
@@ -70,7 +34,6 @@ func (s *APIServer) APIHandler(h http.HandlerFunc) http.HandlerFunc {
 			}
 
 			h(w, r)
-			logrus.Debugf("APIHandler(%s) -- %s %s END", rid, r.Method, r.URL.String())
 		}
 		fn(w, r)
 	}
diff --git a/pkg/api/server/handler_logging.go b/pkg/api/server/handler_logging.go
new file mode 100644
index 000000000..699fab7a5
--- /dev/null
+++ b/pkg/api/server/handler_logging.go
@@ -0,0 +1,51 @@
+package server
+
+import (
+	"io"
+	"io/ioutil"
+	"net/http"
+	"time"
+
+	"github.com/gorilla/mux"
+	"github.com/sirupsen/logrus"
+)
+
+type responseWriter struct {
+	http.ResponseWriter
+}
+
+var apiLogger = &logrus.Logger{
+	Formatter: &logrus.TextFormatter{
+		DisableColors:          true,
+		DisableLevelTruncation: true,
+		FullTimestamp:          true,
+		QuoteEmptyFields:       true,
+		TimestampFormat:        time.RFC3339,
+	},
+	Level: logrus.TraceLevel,
+	Out:   logrus.StandardLogger().Out,
+}
+
+func (l responseWriter) Write(b []byte) (int, error) {
+	apiLogger.WithFields(logrus.Fields{
+		"API":            "response",
+		"X-Reference-Id": l.Header().Get("X-Reference-Id"),
+	}).Trace(string(b))
+	return l.ResponseWriter.Write(b)
+}
+
+func loggingHandler() mux.MiddlewareFunc {
+	return func(h http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			annotated := apiLogger.WithFields(logrus.Fields{
+				"API":            "request",
+				"X-Reference-Id": r.Header.Get("X-Reference-Id"),
+			})
+			r.Body = ioutil.NopCloser(
+				io.TeeReader(r.Body, annotated.WriterLevel(logrus.TraceLevel)))
+
+			w = responseWriter{ResponseWriter: w}
+			h.ServeHTTP(w, r)
+		})
+	}
+}
diff --git a/pkg/api/server/handler_panic.go b/pkg/api/server/handler_panic.go
new file mode 100644
index 000000000..f643db79a
--- /dev/null
+++ b/pkg/api/server/handler_panic.go
@@ -0,0 +1,32 @@
+package server
+
+import (
+	"fmt"
+	"net/http"
+	"runtime"
+
+	"github.com/containers/podman/v3/pkg/api/handlers/utils"
+	"github.com/gorilla/mux"
+	"github.com/sirupsen/logrus"
+)
+
+// panicHandler captures panics from endpoint handlers and logs stack trace
+func panicHandler() mux.MiddlewareFunc {
+	return func(h http.Handler) http.Handler {
+		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+			// http.Server hides panics from handlers, we want to record them and fix the cause
+			defer func() {
+				err := recover()
+				if err != nil {
+					buf := make([]byte, 1<<20)
+					n := runtime.Stack(buf, true)
+					logrus.Warnf("Recovering from API service endpoint handler panic: %v, %s", err, buf[:n])
+					// Try to inform client things went south... won't work if handler already started writing response body
+					utils.InternalServerError(w, fmt.Errorf("%v", err))
+				}
+			}()
+
+			h.ServeHTTP(w, r)
+		})
+	}
+}
diff --git a/pkg/api/server/handler_rid.go b/pkg/api/server/handler_rid.go
new file mode 100644
index 000000000..b624b99a6
--- /dev/null
+++ b/pkg/api/server/handler_rid.go
@@ -0,0 +1,34 @@
+package server
+
+import (
+	"fmt"
+	"net/http"
+
+	"github.com/containers/podman/v3/pkg/api/types"
+	"github.com/google/uuid"
+	"github.com/gorilla/handlers"
+	"github.com/gorilla/mux"
+	"github.com/sirupsen/logrus"
+)
+
+// referenceIDHandler adds X-Reference-Id Header allowing event correlation
+// and Apache style request logging
+func referenceIDHandler() mux.MiddlewareFunc {
+	return func(h http.Handler) http.Handler {
+		return handlers.CombinedLoggingHandler(logrus.StandardLogger().Out,
+			http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				rid := r.Header.Get("X-Reference-Id")
+				if rid == "" {
+					if c := r.Context().Value(types.ConnKey); c == nil {
+						rid = uuid.New().String()
+					} else {
+						rid = fmt.Sprintf("%p", c)
+					}
+				}
+
+				r.Header.Set("X-Reference-Id", rid)
+				w.Header().Set("X-Reference-Id", rid)
+				h.ServeHTTP(w, r)
+			}))
+	}
+}
diff --git a/pkg/api/server/idle/tracker.go b/pkg/api/server/idle/tracker.go
index 687ebd7d4..480239f05 100644
--- a/pkg/api/server/idle/tracker.go
+++ b/pkg/api/server/idle/tracker.go
@@ -1,6 +1,7 @@
 package idle
 
 import (
+	"fmt"
 	"net"
 	"net/http"
 	"sync"
@@ -39,7 +40,10 @@ func (t *Tracker) ConnState(conn net.Conn, state http.ConnState) {
 	t.mux.Lock()
 	defer t.mux.Unlock()
 
-	logrus.Debugf("IdleTracker %p:%v %dm+%dh/%dt connection(s)", conn, state, len(t.managed), t.hijacked, t.TotalConnections())
+	logrus.WithFields(logrus.Fields{
+		"X-Reference-Id": fmt.Sprintf("%p", conn),
+	}).Debugf("IdleTracker:%v %dm+%dh/%dt connection(s)", state, len(t.managed), t.hijacked, t.TotalConnections())
+
 	switch state {
 	case http.StateNew:
 		t.total++
@@ -68,7 +72,9 @@ func (t *Tracker) ConnState(conn net.Conn, state http.ConnState) {
 			if _, found := t.managed[conn]; found {
 				delete(t.managed, conn)
 			} else {
-				logrus.Warnf("IdleTracker %p: StateClosed transition by un-managed connection", conn)
+				logrus.WithFields(logrus.Fields{
+					"X-Reference-Id": fmt.Sprintf("%p", conn),
+				}).Warnf("IdleTracker: StateClosed transition by connection marked un-managed")
 			}
 		}
 
diff --git a/pkg/api/server/server.go b/pkg/api/server/server.go
index 72ae27276..34d0fa246 100644
--- a/pkg/api/server/server.go
+++ b/pkg/api/server/server.go
@@ -7,7 +7,7 @@ import (
 	"net"
 	"net/http"
 	"os"
-	goRuntime "runtime"
+	"runtime"
 	"strings"
 	"sync"
 	"syscall"
@@ -17,11 +17,11 @@ import (
 	"github.com/containers/podman/v3/libpod/shutdown"
 	"github.com/containers/podman/v3/pkg/api/handlers"
 	"github.com/containers/podman/v3/pkg/api/server/idle"
+	"github.com/containers/podman/v3/pkg/api/types"
 	"github.com/coreos/go-systemd/v22/activation"
 	"github.com/coreos/go-systemd/v22/daemon"
 	"github.com/gorilla/mux"
 	"github.com/gorilla/schema"
-	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 )
 
@@ -44,8 +44,10 @@ const (
 	UnlimitedServiceDuration = 0 * time.Second
 )
 
-// shutdownOnce ensures Shutdown() may safely be called from several go routines
-var shutdownOnce sync.Once
+var (
+	// shutdownOnce ensures Shutdown() may safely be called from several go routines
+	shutdownOnce sync.Once
+)
 
 type Options struct {
 	Timeout     time.Duration
@@ -66,15 +68,15 @@ func newServer(runtime *libpod.Runtime, duration time.Duration, listener *net.Li
 	// If listener not provided try socket activation protocol
 	if listener == nil {
 		if _, found := os.LookupEnv("LISTEN_PID"); !found {
-			return nil, errors.Errorf("Cannot create API Server, no listener provided and socket activation protocol is not active.")
+			return nil, fmt.Errorf("no service listener provided and socket activation protocol is not active")
 		}
 
 		listeners, err := activation.Listeners()
 		if err != nil {
-			return nil, errors.Wrap(err, "Cannot retrieve file descriptors from systemd")
+			return nil, fmt.Errorf("cannot retrieve file descriptors from systemd: %w", err)
 		}
 		if len(listeners) != 1 {
-			return nil, errors.Errorf("Wrong number of file descriptors for socket activation protocol (%d != 1)", len(listeners))
+			return nil, fmt.Errorf("wrong number of file descriptors for socket activation protocol (%d != 1)", len(listeners))
 		}
 		listener = &listeners[0]
 	}
@@ -84,24 +86,35 @@ func newServer(runtime *libpod.Runtime, duration time.Duration, listener *net.Li
 		logrus.Debugf("CORS Headers were set to %s", corsHeaders)
 	}
 
-	logrus.Infof("API server listening on %q", (*listener).Addr())
+	logrus.Infof("API service listening on %q", (*listener).Addr())
 	router := mux.NewRouter().UseEncodedPath()
-	idle := idle.NewTracker(duration)
+	tracker := idle.NewTracker(duration)
 
 	server := APIServer{
 		Server: http.Server{
+			ConnContext: func(ctx context.Context, c net.Conn) context.Context {
+				return context.WithValue(ctx, types.ConnKey, c)
+			},
+			ConnState:   tracker.ConnState,
+			ErrorLog:    log.New(logrus.StandardLogger().Out, "", 0),
 			Handler:     router,
 			IdleTimeout: duration * 2,
-			ConnState:   idle.ConnState,
-			ErrorLog:    log.New(logrus.StandardLogger().Out, "", 0),
 		},
-		Decoder:     handlers.NewAPIDecoder(),
-		idleTracker: idle,
-		Listener:    *listener,
-		Runtime:     runtime,
 		CorsHeaders: corsHeaders,
+		Listener:    *listener,
+		idleTracker: tracker,
+	}
+
+	server.BaseContext = func(l net.Listener) context.Context {
+		ctx := context.WithValue(context.Background(), types.DecoderKey, handlers.NewAPIDecoder())
+		ctx = context.WithValue(ctx, types.RuntimeKey, runtime)
+		ctx = context.WithValue(ctx, types.IdleTrackerKey, tracker)
+		return ctx
 	}
 
+	// Capture panics and print stack traces for diagnostics,
+	// additionally process X-Reference-Id Header to support event correlation
+	router.Use(panicHandler(), referenceIDHandler())
 	router.NotFoundHandler = http.HandlerFunc(
 		func(w http.ResponseWriter, r *http.Request) {
 			// We can track user errors...
@@ -149,6 +162,8 @@ func newServer(runtime *libpod.Runtime, duration time.Duration, listener *net.Li
 	}
 
 	if logrus.IsLevelEnabled(logrus.TraceLevel) {
+		// If in trace mode log request and response bodies
+		router.Use(loggingHandler())
 		router.Walk(func(route *mux.Route, r *mux.Router, ancestors []*mux.Route) error { // nolint
 			path, err := route.GetPathTemplate()
 			if err != nil {
@@ -177,13 +192,13 @@ func setupSystemd() {
 	payload := fmt.Sprintf("MAINPID=%d\n", os.Getpid())
 	payload += daemon.SdNotifyReady
 	if sent, err := daemon.SdNotify(true, payload); err != nil {
-		logrus.Errorf("Error notifying systemd of Conmon PID: %s", err.Error())
+		logrus.Error("API service error notifying systemd of Conmon PID: " + err.Error())
 	} else if !sent {
-		logrus.Warn("SDNotify not sent successfully")
+		logrus.Warn("API service unable to successfully send SDNotify")
 	}
 
 	if err := os.Unsetenv("INVOCATION_ID"); err != nil {
-		logrus.Errorf("Error unsetting INVOCATION_ID: %s", err.Error())
+		logrus.Error("API service failed unsetting INVOCATION_ID: " + err.Error())
 	}
 }
 
@@ -205,7 +220,7 @@ func (s *APIServer) Serve() error {
 
 	go func() {
 		<-s.idleTracker.Done()
-		logrus.Debugf("API Server idle for %s", s.idleTracker.Duration.Round(time.Second).String())
+		logrus.Debug("API service shutting down, idle for " + s.idleTracker.Duration.Round(time.Second).String())
 		_ = s.Shutdown()
 	}()
 
@@ -213,12 +228,12 @@ func (s *APIServer) Serve() error {
 		go func() {
 			pprofMux := mux.NewRouter()
 			pprofMux.PathPrefix("/debug/pprof").Handler(http.DefaultServeMux)
-			goRuntime.SetMutexProfileFraction(1)
-			goRuntime.SetBlockProfileRate(1)
+			runtime.SetMutexProfileFraction(1)
+			runtime.SetBlockProfileRate(1)
 			s.pprof = &http.Server{Addr: "localhost:8888", Handler: pprofMux}
 			err := s.pprof.ListenAndServe()
 			if err != nil && err != http.ErrServerClosed {
-				logrus.Warn("Profiler Service failed: " + err.Error())
+				logrus.Warn("API profiler service failed: " + err.Error())
 			}
 		}()
 	}
@@ -230,7 +245,7 @@ func (s *APIServer) Serve() error {
 	go func() {
 		err := s.Server.Serve(s.Listener)
 		if err != nil && err != http.ErrServerClosed {
-			errChan <- errors.Wrap(err, "failed to start API server")
+			errChan <- fmt.Errorf("failed to start API service: %w", err)
 			return
 		}
 		errChan <- nil
@@ -242,14 +257,14 @@ func (s *APIServer) Serve() error {
 // Shutdown is a clean shutdown waiting on existing clients
 func (s *APIServer) Shutdown() error {
 	if s.idleTracker.Duration == UnlimitedServiceDuration {
-		logrus.Debug("APIServer.Shutdown ignored as Duration is UnlimitedService")
+		logrus.Debug("API service shutdown ignored as Duration is UnlimitedService")
 		return nil
 	}
 
 	shutdownOnce.Do(func() {
 		if logrus.IsLevelEnabled(logrus.DebugLevel) {
-			_, file, line, _ := goRuntime.Caller(1)
-			logrus.Debugf("APIServer.Shutdown by %s:%d, %d/%d connection(s)",
+			_, file, line, _ := runtime.Caller(1)
+			logrus.Debugf("API service shutdown by %s:%d, %d/%d connection(s)",
 				file, line, s.idleTracker.ActiveConnections(), s.idleTracker.TotalConnections())
 
 			go func() {
@@ -257,8 +272,7 @@ func (s *APIServer) Shutdown() error {
 				go func() {
 					defer cancel()
 					if err := s.pprof.Shutdown(ctx); err != nil {
-						logrus.Warn(
-							errors.Wrapf(err, "failed to cleanly shutdown pprof Server"))
+						logrus.Warn("Failed to cleanly shutdown API pprof service: " + err.Error())
 					}
 				}()
 				<-ctx.Done()
@@ -272,8 +286,7 @@ func (s *APIServer) Shutdown() error {
 
 			err := s.Server.Shutdown(ctx)
 			if err != nil && err != context.Canceled && err != http.ErrServerClosed {
-				logrus.Error(
-					errors.Wrapf(err, "failed to cleanly shutdown APIServer"))
+				logrus.Error("Failed to cleanly shutdown API service: " + err.Error())
 			}
 		}()
 		<-ctx.Done()