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>
This commit is contained in:
Jhon Honce
2021-09-09 10:13:06 -07:00
parent e6046224ea
commit deaf969243
70 changed files with 1201 additions and 290 deletions

View File

@ -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)
}