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>

1 files changed, 4 insertions, 41 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)
 	}