From a47c605bddcd30f3b468922eb413b53a7fda5446 Mon Sep 17 00:00:00 2001 From: Lucas Manuel Rodriguez Date: Tue, 7 Dec 2021 12:52:43 -0300 Subject: [PATCH] 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 | 1 + server/contexts/logging/logging.go | 13 ++++++--- server/service/endpoint_middleware.go | 33 +++++++++++------------ server/service/integration_logger_test.go | 7 ++--- server/service/service_osquery.go | 24 +---------------- 5 files changed, 31 insertions(+), 47 deletions(-) create mode 100644 changes/issue-missing-error-logs diff --git a/changes/issue-missing-error-logs b/changes/issue-missing-error-logs new file mode 100644 index 0000000000..7277c92ca0 --- /dev/null +++ b/changes/issue-missing-error-logs @@ -0,0 +1 @@ +* Log server request errors that were not being logged when running in non-debug mode. diff --git a/server/contexts/logging/logging.go b/server/contexts/logging/logging.go index 8f470c0677..1816a2c12c 100644 --- a/server/contexts/logging/logging.go +++ b/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 { - logger = level.Info(logger) - } else { + default: logger = level.Debug(logger) } diff --git a/server/service/endpoint_middleware.go b/server/service/endpoint_middleware.go index fba9ed9c85..38230cd118 100644 --- a/server/service/endpoint_middleware.go +++ b/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) { - res, err := authUserFunc(ctx, request) - if err != nil { - logging.WithErr(ctx, err) - return nil, err - } - return res, nil - } + return logged(authUserFunc) } // logged wraps an endpoint and adds the error if the context supports it diff --git a/server/service/integration_logger_test.go b/server/service/integration_logger_test.go index 16ffac4058..7476657561 100644 --- a/server/service/integration_logger_test.go +++ b/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.Contains(t, string(logData["err"]), string(`no matching secret found`)) + assert.Equal(t, `"error"`, string(logData["level"])) + assert.Contains(t, string(logData["err"]), `"enroll failed:`) + assert.Contains(t, string(logData["err"]), `no matching secret found`) } diff --git a/server/service/service_osquery.go b/server/service/service_osquery.go index 3f5656216e..ec41942cd2 100644 --- a/server/service/service_osquery.go +++ b/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"}