summaryrefslogtreecommitdiff
path: root/pkg/api/server
diff options
context:
space:
mode:
Diffstat (limited to 'pkg/api/server')
-rw-r--r--pkg/api/server/handler_api.go45
-rw-r--r--pkg/api/server/handler_logging.go51
-rw-r--r--pkg/api/server/handler_panic.go32
-rw-r--r--pkg/api/server/handler_rid.go34
-rw-r--r--pkg/api/server/idle/tracker.go10
-rw-r--r--pkg/api/server/server.go73
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()
generated by cgit v1.2.3-54-g00ecf (git 2.39.0) at 2024-11-20 00:10:01 +0000