outpost: improve logging output, ensure fields match api server

outpost/pkg/ak/api.go

@@ -49,12 +49,14 @@ func NewAPIController(pbURL url.URL, token string) *APIController {
 	// create the API client, with the transport
 	apiClient := client.New(transport, strfmt.Default)
 
+	log := log.WithField("logger", "authentik.outpost.ak-api-controller")
+
 	// Because we don't know the outpost UUID, we simply do a list and pick the first
 	// The service account this token belongs to should only have access to a single outpost
 	outposts, err := apiClient.Outposts.OutpostsOutpostsList(outposts.NewOutpostsOutpostsListParams(), auth)
 
 	if err != nil {
-		panic(err)
+		log.WithError(err).Panic("Failed to fetch configuration")
 	}
 	outpost := outposts.Payload.Results[0]
 	doGlobalSetup(outpost.Config.(map[string]interface{}))
@@ -64,7 +66,7 @@ func NewAPIController(pbURL url.URL, token string) *APIController {
 		Auth:   auth,
 		token:  token,
 
-		logger: log.WithField("component", "ak-api-controller"),
+		logger: log,
 
 		reloadOffset: time.Duration(rand.Intn(10)) * time.Second,
 

outpost/pkg/ak/api_ws.go

@@ -40,7 +40,7 @@ func (ac *APIController) initWS(pbURL url.URL, outpostUUID strfmt.UUID) {
 	}
 	ws.Dial(fmt.Sprintf(pathTemplate, scheme, pbURL.Host, outpostUUID.String()), header)
 
-	ac.logger.WithField("component", "ak-ws").WithField("outpost", outpostUUID.String()).Debug("connecting to authentik")
+	ac.logger.WithField("logger", "authentik.outpost.ak-ws").WithField("outpost", outpostUUID.String()).Debug("connecting to authentik")
 
 	ac.wsConn = ws
 	// Send hello message with our version
@@ -52,7 +52,7 @@ func (ac *APIController) initWS(pbURL url.URL, outpostUUID strfmt.UUID) {
 	}
 	err := ws.WriteJSON(msg)
 	if err != nil {
-		ac.logger.WithField("component", "ak-ws").WithError(err).Warning("Failed to hello to authentik")
+		ac.logger.WithField("logger", "authentik.outpost.ak-ws").WithError(err).Warning("Failed to hello to authentik")
 	}
 }
 

outpost/pkg/ak/global.go

@@ -13,7 +13,12 @@ import (
 )
 
 func doGlobalSetup(config map[string]interface{}) {
-	log.SetFormatter(&log.JSONFormatter{})
+	log.SetFormatter(&log.JSONFormatter{
+		FieldMap: log.FieldMap{
+			log.FieldKeyMsg:  "event",
+			log.FieldKeyTime: "timestamp",
+		},
+	})
 	switch config[ConfigLogLevel].(string) {
 	case "debug":
 		log.SetLevel(log.DebugLevel)

outpost/pkg/proxy/api.go

@@ -31,7 +31,7 @@ func (s *Server) bundleProviders(providers []*models.ProxyOutpostConfig) []*prov
 		bundles[idx] = &providerBundle{
 			s:    s,
 			Host: externalHost.Host,
-			log:  log.WithField("component", "proxy-bundle").WithField("provider", provider.Name),
+			log:  log.WithField("logger", "authentik.outpost.proxy-bundle").WithField("provider", provider.Name),
 		}
 		bundles[idx].Build(provider)
 	}

outpost/pkg/proxy/api_bundle.go

@@ -129,7 +129,7 @@ func (pb *providerBundle) Build(provider *models.ProxyOutpostConfig) {
 		log.Printf("%s", err)
 		os.Exit(1)
 	}
-	oauthproxy, err := NewOAuthProxy(opts)
+	oauthproxy, err := NewOAuthProxy(opts, provider)
 	if err != nil {
 		log.Errorf("ERROR: Failed to initialise OAuth2 Proxy: %v", err)
 		os.Exit(1)

outpost/pkg/proxy/middleware.go

@@ -95,7 +95,7 @@ type loggingHandler struct {
 func LoggingHandler(h http.Handler) http.Handler {
 	return loggingHandler{
 		handler: h,
-		logger:  log.WithField("component", "proxy-http-server"),
+		logger:  log.WithField("logger", "authentik.outpost.proxy-http-server"),
 	}
 }
 
@@ -104,19 +104,17 @@ func (h loggingHandler) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	url := *req.URL
 	responseLogger := &responseLogger{w: w}
 	h.handler.ServeHTTP(responseLogger, req)
-	duration := float64(time.Since(t)) / float64(time.Second)
+	duration := float64(time.Since(t)) / float64(time.Millisecond)
 	h.logger.WithFields(log.Fields{
-		"Client":          req.RemoteAddr,
-		"Host":            req.Host,
-		"Protocol":        req.Proto,
-		"RequestDuration": fmt.Sprintf("%0.3f", duration),
-		"RequestMethod":   req.Method,
-		"ResponseSize":    responseLogger.Size(),
-		"StatusCode":      responseLogger.Status(),
-		"Timestamp":       t,
-		"Upstream":        responseLogger.upstream,
-		"UserAgent":       req.UserAgent(),
-		"Username":        responseLogger.authInfo,
+		"host":              req.RemoteAddr,
+		"vhost":             req.Host,
+		"request_protocol":  req.Proto,
+		"runtime":           fmt.Sprintf("%0.3f", duration),
+		"method":            req.Method,
+		"size":              responseLogger.Size(),
+		"status":            responseLogger.Status(),
+		"upstream":          responseLogger.upstream,
+		"request_useragent": req.UserAgent(),
+		"request_username":  responseLogger.authInfo,
 	}).Info(url.RequestURI())
-	// logger.PrintReq(responseLogger.authInfo, responseLogger.upstream, req, url, t, , )
 }

outpost/pkg/proxy/proxy.go

@@ -21,6 +21,7 @@ import (
 	"github.com/oauth2-proxy/oauth2-proxy/pkg/sessions"
 	"github.com/oauth2-proxy/oauth2-proxy/pkg/upstream"
 	"github.com/oauth2-proxy/oauth2-proxy/providers"
+	"goauthentik.io/outpost/pkg/models"
 
 	log "github.com/sirupsen/logrus"
 )
@@ -92,8 +93,8 @@ type OAuthProxy struct {
 }
 
 // NewOAuthProxy creates a new instance of OAuthProxy from the options provided
-func NewOAuthProxy(opts *options.Options) (*OAuthProxy, error) {
-	logger := log.WithField("component", "proxy").WithField("client-id", opts.ClientID)
+func NewOAuthProxy(opts *options.Options, provider *models.ProxyOutpostConfig) (*OAuthProxy, error) {
+	logger := log.WithField("logger", "authentik.outpost.proxy").WithField("provider", provider.Name)
 	sessionStore, err := sessions.NewSessionStore(&opts.Session, &opts.Cookie)
 	if err != nil {
 		return nil, fmt.Errorf("error initialising session store: %v", err)
@@ -434,6 +435,7 @@ func (p *OAuthProxy) addHeadersForProxying(rw http.ResponseWriter, req *http.Req
 		authVal := b64.StdEncoding.EncodeToString([]byte(username + ":" + password))
 		req.Header["Authorization"] = []string{fmt.Sprintf("Basic %s", authVal)}
 	}
+	rw.Header().Set("GAP-Auth", session.PreferredUsername)
 	// Check if user has additional headers set that we should sent
 	if additionalHeaders, ok := userAttributes["additionalHeaders"].(map[string]string); ok {
 		if additionalHeaders == nil {

outpost/pkg/proxy/server.go

@@ -6,6 +6,7 @@ import (
 	"errors"
 	"net"
 	"net/http"
+	"strings"
 	"time"
 
 	log "github.com/sirupsen/logrus"
@@ -30,7 +31,7 @@ func NewServer(ac *ak.APIController) *Server {
 	}
 	return &Server{
 		Handlers:    make(map[string]*providerBundle),
-		logger:      log.WithField("component", "proxy-http-server"),
+		logger:      log.WithField("logger", "authentik.outpost.proxy-http-server"),
 		defaultCert: defaultCert,
 		ak:          ac,
 	}
@@ -50,12 +51,15 @@ func (s *Server) handler(w http.ResponseWriter, r *http.Request) {
 				return
 			}
 		}
-		s.logger.WithField("host", r.Host).Debug("Host header does not match any we know of")
-		s.logger.Printf("%v+\n", s.Handlers)
-		w.WriteHeader(400)
+		// Get a list of all host keys we know
+		hostKeys := make([]string, 0, len(s.Handlers))
+		for k := range s.Handlers {
+			hostKeys = append(hostKeys, k)
+		}
+		s.logger.WithField("host", r.Host).WithField("known-hosts", strings.Join(hostKeys, ", ")).Debug("Host header does not match any we know of")
+		w.WriteHeader(404)
 		return
 	}
-	s.logger.WithField("host", r.Host).Debug("passing request from host head")
 	handler.ServeHTTP(w, r)
 }