Log request errors in non-debug mode (take 2) (#3215)

* Log request errors in non-debug mode

* Amend test for debug

* Add check for error log

changes/issue-missing-error-logs

@@ -0,0 +1 @@
+* Log server request errors that were not being logged when running in non-debug mode.

server/contexts/logging/logging.go

@@ -83,21 +83,25 @@ func (l *LoggingContext) SetForceLevel(level func(kitlog.Logger) kitlog.Logger)
 	defer l.l.Unlock()
 	l.ForceLevel = level
 }
+
 func (l *LoggingContext) SetExtras(extras ...interface{}) {
 	l.l.Lock()
 	defer l.l.Unlock()
 	l.Extras = append(l.Extras, extras...)
 }
+
 func (l *LoggingContext) SetSkipUser() {
 	l.l.Lock()
 	defer l.l.Unlock()
 	l.SkipUser = true
 }
+
 func (l *LoggingContext) SetStartTime() {
 	l.l.Lock()
 	defer l.l.Unlock()
 	l.StartTime = time.Now()
 }
+
 func (l *LoggingContext) SetErrs(err ...error) {
 	l.l.Lock()
 	defer l.l.Unlock()
@@ -109,11 +113,12 @@ func (l *LoggingContext) Log(ctx context.Context, logger kitlog.Logger) {
 	l.l.Lock()
 	defer l.l.Unlock()
 
-	if l.ForceLevel != nil {
+	switch {
+	case len(l.Errs) > 0:
+		logger = level.Error(logger)
+	case l.ForceLevel != nil:
 		logger = l.ForceLevel(logger)
-	} else if l.Errs != nil || len(l.Extras) > 0 {
+	default:
-		logger = level.Info(logger)
-	} else {
 		logger = level.Debug(logger)
 	}
 

server/service/endpoint_middleware.go

@@ -10,6 +10,7 @@ import (
 	"github.com/fleetdm/fleet/v4/server/fleet"
 	"github.com/go-kit/kit/log"
 	"github.com/go-kit/kit/log/level"
+	kithttp "github.com/go-kit/kit/transport/http"
 
 	hostctx "github.com/fleetdm/fleet/v4/server/contexts/host"
 	"github.com/fleetdm/fleet/v4/server/contexts/token"
@@ -26,11 +27,21 @@ func logJSON(logger log.Logger, v interface{}, key string) {
 	level.Debug(logger).Log(key, string(jsonV))
 }
 
+// instrumentHostLogger adds host IP information and extras to the context logger.
+func instrumentHostLogger(ctx context.Context, extras ...interface{}) {
+	remoteAddr, _ := ctx.Value(kithttp.ContextKeyRequestRemoteAddr).(string)
+	xForwardedFor, _ := ctx.Value(kithttp.ContextKeyRequestXForwardedFor).(string)
+	logging.WithExtras(
+		logging.WithNoUser(ctx),
+		append(extras, "ip_addr", remoteAddr, "x_for_ip_addr", xForwardedFor)...,
+	)
+}
+
 // authenticatedHost wraps an endpoint, checks the validity of the node_key
 // provided in the request, and attaches the corresponding osquery host to the
 // context for the request
 func authenticatedHost(svc fleet.Service, logger log.Logger, next endpoint.Endpoint) endpoint.Endpoint {
-	return func(ctx context.Context, request interface{}) (interface{}, error) {
+	authHostFunc := func(ctx context.Context, request interface{}) (interface{}, error) {
 		nodeKey, err := getNodeKey(request)
 		if err != nil {
 			return nil, err
@@ -48,24 +59,19 @@ func authenticatedHost(svc fleet.Service, logger log.Logger, next endpoint.Endpo
 		}
 
 		ctx = hostctx.NewContext(ctx, *host)
+		instrumentHostLogger(ctx)
+
 		resp, err := next(ctx, request)
 		if err != nil {
-			logging.WithErr(ctx, err)
 			return nil, err
 		}
 
 		if debug {
 			logJSON(hlogger, request, "response")
 		}
-
-		if errResp, ok := resp.(errorer); ok {
-			err = errResp.error()
-			if err != nil {
-				logging.WithErr(ctx, err)
-			}
-		}
 		return resp, nil
 	}
+	return logged(authHostFunc)
 }
 
 func getNodeKey(r interface{}) (string, error) {
@@ -125,14 +131,7 @@ func authenticatedUser(svc fleet.Service, next endpoint.Endpoint) endpoint.Endpo
 		return next(ctx, request)
 	}
 
-	return func(ctx context.Context, request interface{}) (response interface{}, err error) {
+	return logged(authUserFunc)
-		res, err := authUserFunc(ctx, request)
-		if err != nil {
-			logging.WithErr(ctx, err)
-			return nil, err
-		}
-		return res, nil
-	}
 }
 
 // logged wraps an endpoint and adds the error if the context supports it

server/service/integration_logger_test.go

@@ -85,7 +85,7 @@ func (s *integrationLoggerTestSuite) TestLogger() {
 			assert.Equal(t, "/api/v1/fleet/config", kv["uri"])
 			assert.Equal(t, "admin1@example.com", kv["user"])
 		case 2:
-			assert.Equal(t, "info", kv["level"])
+			assert.Equal(t, "debug", kv["level"])
 			assert.Equal(t, "POST", kv["method"])
 			assert.Equal(t, "/api/v1/fleet/queries", kv["uri"])
 			assert.Equal(t, "admin1@example.com", kv["user"])
@@ -184,6 +184,7 @@ func (s *integrationLoggerTestSuite) TestEnrollAgentLogsErrors() {
 	require.Len(t, parts, 1)
 	logData := make(map[string]json.RawMessage)
 	require.NoError(t, json.Unmarshal([]byte(parts[0]), &logData))
-	assert.Contains(t, string(logData["err"]), string(`"enroll failed:`))
+	assert.Equal(t, `"error"`, string(logData["level"]))
-	assert.Contains(t, string(logData["err"]), string(`no matching secret found`))
+	assert.Contains(t, string(logData["err"]), `"enroll failed:`)
+	assert.Contains(t, string(logData["err"]), `no matching secret found`)
 }

server/service/service_osquery.go

@@ -17,7 +17,6 @@ import (
 	"github.com/fleetdm/fleet/v4/server/contexts/logging"
 	"github.com/fleetdm/fleet/v4/server/ptr"
 	"github.com/fleetdm/fleet/v4/server/service/osquery_utils"
-	kithttp "github.com/go-kit/kit/transport/http"
 
 	"github.com/fleetdm/fleet/v4/server/fleet"
 
@@ -104,7 +103,7 @@ func (svc Service) EnrollAgent(ctx context.Context, enrollSecret, hostIdentifier
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx, "hostIdentifier", hostIdentifier)
+	logging.WithExtras(ctx, "hostIdentifier", hostIdentifier)
 
 	secret, err := svc.ds.VerifyEnrollSecret(ctx, enrollSecret)
 	if err != nil {
@@ -257,8 +256,6 @@ func (svc *Service) GetClientConfig(ctx context.Context) (map[string]interface{}
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx)
-
 	host, ok := hostctx.FromContext(ctx)
 	if !ok {
 		return nil, osqueryError{message: "internal error: missing host from request context"}
@@ -382,31 +379,16 @@ func (svc *Service) SubmitStatusLogs(ctx context.Context, logs []json.RawMessage
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx)
-
 	if err := svc.osqueryLogWriter.Status.Write(ctx, logs); err != nil {
 		return osqueryError{message: "error writing status logs: " + err.Error()}
 	}
 	return nil
 }
 
-func logIPs(ctx context.Context, extras ...interface{}) {
-	remoteAddr, _ := ctx.Value(kithttp.ContextKeyRequestRemoteAddr).(string)
-	xForwardedFor, _ := ctx.Value(kithttp.ContextKeyRequestXForwardedFor).(string)
-	logging.WithLevel(
-		logging.WithExtras(
-			logging.WithNoUser(ctx),
-			append(extras, "ip_addr", remoteAddr, "x_for_ip_addr", xForwardedFor)...),
-		level.Debug,
-	)
-}
-
 func (svc *Service) SubmitResultLogs(ctx context.Context, logs []json.RawMessage) error {
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx)
-
 	if err := svc.osqueryLogWriter.Result.Write(ctx, logs); err != nil {
 		return osqueryError{message: "error writing result logs: " + err.Error()}
 	}
@@ -512,8 +494,6 @@ func (svc *Service) GetDistributedQueries(ctx context.Context) (map[string]strin
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx)
-
 	host, ok := hostctx.FromContext(ctx)
 	if !ok {
 		return nil, 0, osqueryError{message: "internal error: missing host from request context"}
@@ -691,8 +671,6 @@ func (svc *Service) SubmitDistributedQueryResults(
 	// skipauth: Authorization is currently for user endpoints only.
 	svc.authz.SkipAuthorization(ctx)
 
-	logIPs(ctx)
-
 	host, ok := hostctx.FromContext(ctx)
 	if !ok {
 		return osqueryError{message: "internal error: missing host from request context"}