From 366d9e95aa299e98bb40dd5d0fa487cf3d5f0d21 Mon Sep 17 00:00:00 2001 From: Todd Date: Thu, 22 Feb 2024 10:20:48 -0800 Subject: [PATCH] Add Error logging and hclog.Logger debug logging throughout the daemon (#4384) (#4439) * Save and assign hclogger throughout the client cache daemon * Don't event for errors happening outside of the handlers or tickers. * Hide and ignore -store-debug and expose the -log-level flag --- internal/clientcache/cmd/daemon/start.go | 12 +-- .../clientcache/internal/cache/refresh.go | 61 ++++++++------- .../internal/cache/refresh_test.go | 29 ++++---- .../internal/cache/repository_token.go | 50 ++++++------- internal/clientcache/internal/cache/search.go | 10 +-- .../clientcache/internal/daemon/options.go | 29 +++++--- .../internal/daemon/options_test.go | 15 +++- .../internal/daemon/search_handler.go | 27 +++++-- .../clientcache/internal/daemon/server.go | 74 ++++++++++--------- .../clientcache/internal/daemon/testing.go | 9 +-- .../internal/daemon/token_handler.go | 54 +++++++++++--- .../internal/daemon/token_handler_test.go | 51 ++++++++++++- internal/clientcache/internal/db/db.go | 9 ++- internal/clientcache/internal/db/options.go | 15 +++- 14 files changed, 298 insertions(+), 147 deletions(-) diff --git a/internal/clientcache/cmd/daemon/start.go b/internal/clientcache/cmd/daemon/start.go index 88812a51c..b4a5d5a5c 100644 --- a/internal/clientcache/cmd/daemon/start.go +++ b/internal/clientcache/cmd/daemon/start.go @@ -82,7 +82,6 @@ func (c *StartCommand) Flags() *base.FlagSets { Completion: complete.PredictSet("trace", "debug", "info", "warn", "err"), Usage: "Log verbosity level, mostly as a fallback for events. Supported values (in order of more detail to less) are " + "\"trace\", \"debug\", \"info\", \"warn\", and \"err\".", - Hidden: true, }) f.StringVar(&base.StringVar{ Name: "log-format", @@ -125,8 +124,9 @@ func (c *StartCommand) Flags() *base.FlagSets { Name: "store-debug", Target: &c.flagStoreDebug, Default: false, - Usage: `Turn on sqlite query debugging`, + Usage: `Turn on sqlite query debugging. This is deprecated. Users should use -log-level=debug instead.`, Aliases: []string{"d"}, + Hidden: true, }) f.BoolVar(&base.BoolVar{ Name: "background", @@ -191,6 +191,10 @@ func (c *StartCommand) Run(args []string) int { defer lf.Close() writers = append(writers, lf) + if c.flagStoreDebug { + c.UI.Warn("The -store-debug flag is now ignored. Use -log-level=debug instead for debugging purposes.") + } + cfg := &daemon.Config{ ContextCancel: cancel, RefreshInterval: c.flagRefreshInterval, @@ -198,7 +202,6 @@ func (c *StartCommand) Run(args []string) int { MaxSearchStaleness: c.flagMaxSearchStaleness, MaxSearchRefreshTimeout: c.flagMaxSearchRefreshTimeout, DatabaseUrl: c.flagDatabaseUrl, - StoreDebug: c.flagStoreDebug, LogLevel: c.flagLogLevel, LogFormat: c.flagLogFormat, LogWriter: io.MultiWriter(writers...), @@ -319,9 +322,6 @@ func (c *StartCommand) makeBackground(ctx context.Context, dotDir string) (bool, if c.flagDatabaseUrl != "" { args = append(args, "-database-url", c.flagDatabaseUrl) } - if c.flagStoreDebug { - args = append(args, "-store-debug") - } cmd := exec.Command(absPath, args...) cmd.Env = env if err = cmd.Start(); err != nil { diff --git a/internal/clientcache/internal/cache/refresh.go b/internal/clientcache/internal/cache/refresh.go index 4e6c796ae..d8a6bd143 100644 --- a/internal/clientcache/internal/cache/refresh.go +++ b/internal/clientcache/internal/cache/refresh.go @@ -14,10 +14,13 @@ import ( "github.com/hashicorp/boundary/internal/errors" "github.com/hashicorp/boundary/internal/event" "github.com/hashicorp/boundary/internal/util" + "github.com/hashicorp/go-hclog" ) type RefreshService struct { repo *Repository + + logger hclog.Logger // the amount of time that should have passed since the last refresh for a // call to RefreshForSearch will cause a refresh request to be sent to a // boundary controller. @@ -26,16 +29,19 @@ type RefreshService struct { maxSearchRefreshTimeout time.Duration } -func NewRefreshService(ctx context.Context, r *Repository, maxSearchStaleness, maxSearchRefreshTimeout time.Duration) (*RefreshService, error) { +func NewRefreshService(ctx context.Context, r *Repository, logger hclog.Logger, maxSearchStaleness, maxSearchRefreshTimeout time.Duration) (*RefreshService, error) { const op = "cache.NewRefreshService" switch { case util.IsNil(r): return nil, errors.New(ctx, errors.InvalidParameter, op, "repository is nil") + case util.IsNil(logger): + return nil, errors.New(ctx, errors.InvalidParameter, op, "logger is nil") case maxSearchStaleness < 0: return nil, errors.New(ctx, errors.InvalidParameter, op, "max search staleness is negative") } return &RefreshService{ repo: r, + logger: logger, maxSearchStaleness: maxSearchStaleness, maxSearchRefreshTimeout: maxSearchRefreshTimeout, }, nil @@ -66,10 +72,11 @@ func (r *RefreshService) cleanAndPickAuthTokens(ctx context.Context, u *user) (m at := r.repo.tokenKeyringFn(kt.KeyringType, kt.TokenName) switch { case at == nil, at.Id != kt.AuthTokenId, at.UserId != t.UserId: + event.WriteSysEvent(ctx, op, "Removed keyring token since the keyring contents have changed since being cached", "keyring", kt.KeyringType, "token name", kt.TokenName, "old auth token id", kt.AuthTokenId) // delete the keyring token if the auth token in the keyring // has changed since it was stored in the cache. if err := r.repo.deleteKeyringToken(ctx, *kt); err != nil { - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithMsg("for user %q, auth token %q", u.Id, t.Id)) } case at != nil: _, err := r.repo.tokenReadFromBoundaryFn(ctx, u.Address, at.Token) @@ -77,7 +84,7 @@ func (r *RefreshService) cleanAndPickAuthTokens(ctx context.Context, u *user) (m switch { case err != nil && (api.ErrUnauthorized.Is(err) || api.ErrNotFound.Is(err)): if err := r.repo.deleteKeyringToken(ctx, *kt); err != nil { - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithMsg("for user %q, auth token %q", u.Id, t.Id)) } event.WriteSysEvent(ctx, op, "Removed auth token from cache because it was not found to be valid in boundary", "auth token id", at.Id) continue @@ -119,7 +126,7 @@ func (r *RefreshService) cacheSupportedUsers(ctx context.Context, in []*user) ([ for _, u := range in { cs, err := r.repo.cacheSupportState(ctx, u) if err != nil { - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithMsg("for user %q", u.Id)) } if cs.supported != NotSupportedCacheSupport { ret = append(ret, u) @@ -152,21 +159,21 @@ func (r *RefreshService) RefreshForSearch(ctx context.Context, authTokenid strin } at, err := r.repo.LookupToken(ctx, authTokenid) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if at == nil { - return errors.New(ctx, errors.NotFound, op, "auth token not found") + return errors.New(ctx, errors.NotFound, op, "auth token not found", errors.WithoutEvent()) } u, err := r.repo.lookupUser(ctx, at.UserId) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if u == nil { - return errors.New(ctx, errors.NotFound, op, "user not found") + return errors.New(ctx, errors.NotFound, op, "user not found", errors.WithoutEvent()) } us, err := r.cacheSupportedUsers(ctx, []*user{u}) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } switch len(us) { @@ -176,28 +183,29 @@ func (r *RefreshService) RefreshForSearch(ctx context.Context, authTokenid strin case 1: u = us[0] default: - return errors.New(ctx, errors.Internal, op, "unexpected number of refreshable users") + return errors.New(ctx, errors.Internal, op, "unexpected number of refreshable users", errors.WithoutEvent()) } tokens, err := r.cleanAndPickAuthTokens(ctx, u) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } opts, err := getOpts(opt...) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } switch resourceType { case Targets: rtv, err := r.repo.lookupRefreshToken(ctx, u, targetResourceType) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if opts.withIgnoreSearchStaleness || rtv != nil && time.Since(rtv.UpdateTime) > r.maxSearchStaleness { + r.logger.Debug("refreshing targets before performing search", "user", u.Id, "force refresh", opts.withIgnoreSearchStaleness, "sessions age", time.Since(rtv.UpdateTime)) if err := r.repo.refreshTargets(ctx, u, tokens, opt...); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } } case Sessions: @@ -206,12 +214,13 @@ func (r *RefreshService) RefreshForSearch(ctx context.Context, authTokenid strin return errors.Wrap(ctx, err, op) } if opts.withIgnoreSearchStaleness || rtv != nil && time.Since(rtv.UpdateTime) > r.maxSearchStaleness { + r.logger.Debug("refreshing sessions before performing search", "user", u.Id, "force refresh", opts.withIgnoreSearchStaleness, "sessions age", time.Since(rtv.UpdateTime)) if err := r.repo.refreshSessions(ctx, u, tokens, opt...); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } } default: - return errors.New(ctx, errors.InvalidParameter, op, "unrecognized resource type") + return errors.New(ctx, errors.InvalidParameter, op, "unrecognized resource type", errors.WithoutEvent()) } return nil @@ -226,27 +235,28 @@ func (r *RefreshService) RefreshForSearch(ctx context.Context, authTokenid strin func (r *RefreshService) Refresh(ctx context.Context, opt ...Option) error { const op = "cache.(RefreshService).Refresh" if err := r.repo.cleanExpiredOrOrphanedAuthTokens(ctx); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if err := r.repo.syncKeyringlessTokensWithDb(ctx); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } us, err := r.repo.listUsers(ctx) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } us, err = r.cacheSupportedUsers(ctx, us) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } var retErr error for _, u := range us { + r.logger.Debug("refreshing user", "user", u.Id) tokens, err := r.cleanAndPickAuthTokens(ctx, u) if err != nil { - retErr = stderrors.Join(retErr, errors.Wrap(ctx, err, op)) + retErr = stderrors.Join(retErr, errors.Wrap(ctx, err, op, errors.WithoutEvent())) continue } @@ -270,20 +280,20 @@ func (r *RefreshService) Refresh(ctx context.Context, opt ...Option) error { func (r *RefreshService) RecheckCachingSupport(ctx context.Context, opt ...Option) error { const op = "cache.(RefreshService).RecheckCachingSupport" if err := r.repo.cleanExpiredOrOrphanedAuthTokens(ctx); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if err := r.repo.syncKeyringlessTokensWithDb(ctx); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } us, err := r.repo.listUsers(ctx) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } removeUsers, err := r.cacheSupportedUsers(ctx, us) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } removedUserIds := make(map[string]struct{}, len(removeUsers)) for _, ru := range removeUsers { @@ -295,6 +305,7 @@ func (r *RefreshService) RecheckCachingSupport(ctx context.Context, opt ...Optio if _, ok := removedUserIds[u.Id]; ok { continue } + r.logger.Debug("rechecking caching support for user", "user", u.Id) tokens, err := r.cleanAndPickAuthTokens(ctx, u) if err != nil { diff --git a/internal/clientcache/internal/cache/refresh_test.go b/internal/clientcache/internal/cache/refresh_test.go index 5ade53ed5..588af254b 100644 --- a/internal/clientcache/internal/cache/refresh_test.go +++ b/internal/clientcache/internal/cache/refresh_test.go @@ -17,6 +17,7 @@ import ( "github.com/hashicorp/boundary/api/sessions" "github.com/hashicorp/boundary/api/targets" "github.com/hashicorp/boundary/internal/clientcache/internal/db" + "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "golang.org/x/exp/maps" @@ -139,7 +140,7 @@ func TestCleanAndPickTokens(t *testing.T) { mapBasedAuthTokenKeyringLookup(atMap), fakeBoundaryLookupFn) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) t.Run("unknown user", func(t *testing.T) { @@ -355,7 +356,7 @@ func TestRefreshForSearch(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, time.Millisecond, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), time.Millisecond, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -406,7 +407,7 @@ func TestRefreshForSearch(t *testing.T) { r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) // Everything can stay stale for an hour - rs, err := NewRefreshService(ctx, r, time.Hour, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), time.Hour, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -460,7 +461,7 @@ func TestRefreshForSearch(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -513,7 +514,7 @@ func TestRefreshForSearch(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -561,7 +562,7 @@ func TestRefreshForSearch(t *testing.T) { r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) // Everything stays fresh for 1 hour - rs, err := NewRefreshService(ctx, r, time.Hour, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), time.Hour, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -632,7 +633,7 @@ func TestRefresh(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -673,7 +674,7 @@ func TestRefresh(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -713,7 +714,7 @@ func TestRefresh(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -741,7 +742,7 @@ func TestRefresh(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -795,7 +796,7 @@ func TestRecheckCachingSupport(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -829,7 +830,7 @@ func TestRecheckCachingSupport(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -863,7 +864,7 @@ func TestRecheckCachingSupport(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) @@ -897,7 +898,7 @@ func TestRecheckCachingSupport(t *testing.T) { require.NoError(t, err) r, err := NewRepository(ctx, s, &sync.Map{}, mapBasedAuthTokenKeyringLookup(atMap), sliceBasedAuthTokenBoundaryReader(boundaryAuthTokens)) require.NoError(t, err) - rs, err := NewRefreshService(ctx, r, 0, 0) + rs, err := NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, r.AddKeyringToken(ctx, boundaryAddr, KeyringToken{KeyringType: "k", TokenName: "t", AuthTokenId: at.Id})) diff --git a/internal/clientcache/internal/cache/repository_token.go b/internal/clientcache/internal/cache/repository_token.go index 6a17b0ef6..055a1b7e3 100644 --- a/internal/clientcache/internal/cache/repository_token.go +++ b/internal/clientcache/internal/cache/repository_token.go @@ -112,15 +112,15 @@ func (r *Repository) AddRawToken(ctx context.Context, bAddr string, rawToken str const op = "cache.(Repository).AddRawToken" switch { case rawToken == "": - return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token is empty") + return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token is empty", errors.WithoutEvent()) case bAddr == "": - return errors.New(ctx, errors.InvalidParameter, op, "boundary address is empty") + return errors.New(ctx, errors.InvalidParameter, op, "boundary address is empty", errors.WithoutEvent()) } // rawToken should look something like at_1234567890_someencryptedpayload atIdParts := strings.SplitN(rawToken, "_", 4) if len(atIdParts) != 3 { - return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token is is malformed") + return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token is is malformed", errors.WithoutEvent()) } atId := strings.Join(atIdParts[:AuthTokenIdSegmentCount], "_") @@ -132,7 +132,7 @@ func (r *Repository) AddRawToken(ctx context.Context, bAddr string, rawToken str var ok bool inMemAuthToken, ok = atV.(*authtokens.AuthToken) if !ok { - return errors.New(ctx, errors.Internal, op, "unable to cast in memory auth token to *authtoken.AuthToken") + return errors.New(ctx, errors.Internal, op, "unable to cast in memory auth token to *authtoken.AuthToken", errors.WithoutEvent()) } } t := &AuthToken{ @@ -148,10 +148,10 @@ func (r *Repository) AddRawToken(ctx context.Context, bAddr string, rawToken str // cache information about this auth token. at, err = r.tokenReadFromBoundaryFn(ctx, bAddr, rawToken) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } case t.UserId != inMemAuthToken.UserId: - return errors.New(ctx, errors.InvalidParameter, op, "user id doesn't match what is specified in the stored auth token") + return errors.New(ctx, errors.InvalidParameter, op, "user id doesn't match what is specified in the stored auth token", errors.WithoutEvent()) case inMem: at = inMemAuthToken } @@ -165,7 +165,7 @@ func (r *Repository) AddRawToken(ctx context.Context, bAddr string, rawToken str _, err := r.rw.DoTx(ctx, db.StdRetryCnt, db.ExpBackoff{}, func(reader db.Reader, writer db.Writer) error { if err := upsertUserAndAuthToken(ctx, reader, writer, bAddr, at); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } r.idToKeyringlessAuthToken.Store(at.Id, at) return nil @@ -186,21 +186,21 @@ func (r *Repository) AddKeyringToken(ctx context.Context, bAddr string, token Ke const op = "cache.(Repository).AddKeyringToken" switch { case token.TokenName == "": - return errors.New(ctx, errors.InvalidParameter, op, "token name is empty") + return errors.New(ctx, errors.InvalidParameter, op, "token name is empty", errors.WithoutEvent()) case token.KeyringType == "": - return errors.New(ctx, errors.InvalidParameter, op, "keyring type is empty") + return errors.New(ctx, errors.InvalidParameter, op, "keyring type is empty", errors.WithoutEvent()) case token.AuthTokenId == "": - return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token id is empty") + return errors.New(ctx, errors.InvalidParameter, op, "boundary auth token id is empty", errors.WithoutEvent()) case bAddr == "": - return errors.New(ctx, errors.InvalidParameter, op, "boundary address is empty") + return errors.New(ctx, errors.InvalidParameter, op, "boundary address is empty", errors.WithoutEvent()) } kt := token.clone() keyringStoredAt := r.tokenKeyringFn(kt.KeyringType, kt.TokenName) if keyringStoredAt == nil { - return errors.New(ctx, errors.InvalidParameter, op, "unable to find token in the keyring specified") + return errors.New(ctx, errors.InvalidParameter, op, "unable to find token in the keyring specified", errors.WithoutEvent()) } if kt.AuthTokenId != keyringStoredAt.Id { - return errors.New(ctx, errors.InvalidParameter, op, "provided auth token id doesn't match the one stored") + return errors.New(ctx, errors.InvalidParameter, op, "provided auth token id doesn't match the one stored", errors.WithoutEvent()) } var at *authtokens.AuthToken @@ -218,21 +218,21 @@ func (r *Repository) AddKeyringToken(ctx context.Context, bAddr string, token Ke return errors.Wrap(ctx, err, op) } case cachedAt.UserId != keyringStoredAt.UserId: - return errors.New(ctx, errors.InvalidParameter, op, "user id doesn't match what is specified in the stored auth token") + return errors.New(ctx, errors.InvalidParameter, op, "user id doesn't match what is specified in the stored auth token", errors.WithoutEvent()) default: at = keyringStoredAt } } _, err := r.rw.DoTx(ctx, db.StdRetryCnt, db.ExpBackoff{}, func(reader db.Reader, writer db.Writer) error { if err := upsertUserAndAuthToken(ctx, reader, writer, bAddr, at); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } onConflict := &db.OnConflict{ Target: db.Columns{"keyring_type", "token_name"}, Action: db.SetColumns([]string{"auth_token_id"}), } if err := writer.Create(ctx, kt, db.WithOnConflict(onConflict)); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } return nil }) @@ -252,7 +252,7 @@ func (r *Repository) LookupToken(ctx context.Context, authTokenId string, opt .. const op = "cache.(Repository).LookupToken" switch { case authTokenId == "": - return nil, errors.New(ctx, errors.InvalidParameter, op, "auth token id is empty") + return nil, errors.New(ctx, errors.InvalidParameter, op, "auth token id is empty", errors.WithoutEvent()) } at := &AuthToken{ @@ -262,12 +262,12 @@ func (r *Repository) LookupToken(ctx context.Context, authTokenId string, opt .. if errors.IsNotFoundError(err) { return nil, nil } - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithoutEvent()) } opts, err := getOpts(opt...) if err != nil { - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if opts.withUpdateLastAccessedTime { @@ -276,7 +276,7 @@ func (r *Repository) LookupToken(ctx context.Context, authTokenId string, opt .. LastAccessedTime: time.Now(), } if _, err := r.rw.Update(ctx, updatedT, []string{"LastAccessedTime"}, nil); err != nil { - return nil, errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op, errors.WithoutEvent()) } } return at, nil @@ -300,19 +300,19 @@ func (r *Repository) deleteKeyringToken(ctx context.Context, kt KeyringToken) er // query here. n, err := writer.Exec(ctx, "delete from keyring_token where (keyring_type, token_name) = (?, ?)", []any{kt.KeyringType, kt.TokenName}) if err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } switch n { case 1: if err := cleanExpiredOrOrphanedAuthTokens(ctx, writer, r.idToKeyringlessAuthToken); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } return nil case 0: - return errors.New(ctx, errors.RecordNotFound, op, "token not found when attempting deletion") + return errors.New(ctx, errors.RecordNotFound, op, "token not found when attempting deletion", errors.WithoutEvent()) default: - return errors.New(ctx, errors.MultipleRecords, op, "multiple tokens deleted when one was requested") + return errors.New(ctx, errors.MultipleRecords, op, "multiple tokens deleted when one was requested", errors.WithoutEvent()) } }) if err != nil { @@ -327,7 +327,7 @@ func (r *Repository) cleanExpiredOrOrphanedAuthTokens(ctx context.Context) error const op = "cache.Repository.cleanExpiredOrOrphanedAuthTokens" _, err := r.rw.DoTx(ctx, db.StdRetryCnt, db.ExpBackoff{}, func(reader db.Reader, writer db.Writer) error { if err := cleanExpiredOrOrphanedAuthTokens(ctx, writer, r.idToKeyringlessAuthToken); err != nil { - return errors.Wrap(ctx, err, op) + return errors.Wrap(ctx, err, op, errors.WithoutEvent()) } return nil }) diff --git a/internal/clientcache/internal/cache/search.go b/internal/clientcache/internal/cache/search.go index b96ae931a..ebc37e511 100644 --- a/internal/clientcache/internal/cache/search.go +++ b/internal/clientcache/internal/cache/search.go @@ -99,20 +99,20 @@ func (s *SearchService) Supported(ctx context.Context, t *AuthToken) (bool, erro const op = "cache.(SearchService).Supported" switch { case util.IsNil(t): - return false, errors.New(ctx, errors.InvalidParameter, op, "auth token is nil") + return false, errors.New(ctx, errors.InvalidParameter, op, "auth token is nil", errors.WithoutEvent()) case t.UserId == "": - return false, errors.New(ctx, errors.InvalidParameter, op, "auth token's user id is empty") + return false, errors.New(ctx, errors.InvalidParameter, op, "auth token's user id is empty", errors.WithoutEvent()) } u, err := s.repo.lookupUser(ctx, t.UserId) if err != nil { - return false, errors.Wrap(ctx, err, op) + return false, errors.Wrap(ctx, err, op, errors.WithoutEvent()) } if u == nil { - return false, errors.New(ctx, errors.NotFound, op, "user not found for auth token") + return false, errors.New(ctx, errors.NotFound, op, "user not found for auth token", errors.WithoutEvent()) } cs, err := s.repo.cacheSupportState(ctx, u) if err != nil { - return false, errors.Wrap(ctx, err, op) + return false, errors.Wrap(ctx, err, op, errors.WithoutEvent()) } return cs.supported != NotSupportedCacheSupport, nil } diff --git a/internal/clientcache/internal/daemon/options.go b/internal/clientcache/internal/daemon/options.go index f8bc67b3b..fca393061 100644 --- a/internal/clientcache/internal/daemon/options.go +++ b/internal/clientcache/internal/daemon/options.go @@ -9,15 +9,18 @@ import ( "time" "github.com/hashicorp/boundary/internal/clientcache/internal/cache" + "github.com/hashicorp/go-hclog" ) type options struct { - withDebug bool withRefreshInterval time.Duration withRecheckSupportInterval time.Duration testWithIntervalRandomizationFactor float64 testWithIntervalRandomizationFactorSet bool withBoundaryTokenReaderFunc cache.BoundaryTokenReaderFn + + withUrl string + withLogger hclog.Logger } // Option - how options are passed as args @@ -38,14 +41,6 @@ func getOpts(opt ...Option) (options, error) { return opts, nil } -// WithDebug provides an optional debug flag. -func WithDebug(_ context.Context, debug bool) Option { - return func(o *options) error { - o.withDebug = debug - return nil - } -} - // withRefreshInterval provides an optional refresh interval. func withRefreshInterval(_ context.Context, d time.Duration) Option { return func(o *options) error { @@ -81,6 +76,22 @@ func testWithIntervalRandomizationFactor(_ context.Context, f float64) Option { } } +// WithUrl provides optional url +func WithUrl(_ context.Context, url string) Option { + return func(o *options) error { + o.withUrl = url + return nil + } +} + +// WithLogger provides an optional logger. +func WithLogger(_ context.Context, logger hclog.Logger) Option { + return func(o *options) error { + o.withLogger = logger + return nil + } +} + // WithBoundaryTokenReaderFunc provides an option for specifying a BoundaryTokenReaderFn func WithBoundaryTokenReaderFunc(_ context.Context, fn cache.BoundaryTokenReaderFn) Option { return func(o *options) error { diff --git a/internal/clientcache/internal/daemon/options_test.go b/internal/clientcache/internal/daemon/options_test.go index 4abe13b26..c87eef396 100644 --- a/internal/clientcache/internal/daemon/options_test.go +++ b/internal/clientcache/internal/daemon/options_test.go @@ -10,6 +10,7 @@ import ( "github.com/hashicorp/boundary/api/authtokens" "github.com/hashicorp/boundary/internal/clientcache/internal/cache" + "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -24,11 +25,19 @@ func Test_GetOpts(t *testing.T) { testOpts := options{} assert.Equal(t, opts, testOpts) }) - t.Run("WithDebug", func(t *testing.T) { - opts, err := getOpts(WithDebug(ctx, true)) + t.Run("WithUrl", func(t *testing.T) { + opts, err := getOpts(WithUrl(ctx, "http://localhost:9200")) require.NoError(t, err) testOpts := getDefaultOptions() - testOpts.withDebug = true + testOpts.withUrl = "http://localhost:9200" + assert.Equal(t, opts, testOpts) + }) + t.Run("WithLogger", func(t *testing.T) { + testLogger := hclog.NewNullLogger() + opts, err := getOpts(WithLogger(ctx, testLogger)) + require.NoError(t, err) + testOpts := getDefaultOptions() + testOpts.withLogger = testLogger assert.Equal(t, opts, testOpts) }) t.Run("withRefreshInterval", func(t *testing.T) { diff --git a/internal/clientcache/internal/daemon/search_handler.go b/internal/clientcache/internal/daemon/search_handler.go index f4727a779..4597c3b7d 100644 --- a/internal/clientcache/internal/daemon/search_handler.go +++ b/internal/clientcache/internal/daemon/search_handler.go @@ -17,6 +17,7 @@ import ( "github.com/hashicorp/boundary/internal/errors" "github.com/hashicorp/boundary/internal/event" "github.com/hashicorp/boundary/internal/util" + "github.com/hashicorp/go-hclog" ) // SearchResult is the struct returned to search requests. @@ -33,11 +34,13 @@ const ( authTokenIdKey = "auth_token_id" ) -func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshService *cache.RefreshService) (http.HandlerFunc, error) { +func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshService *cache.RefreshService, logger hclog.Logger) (http.HandlerFunc, error) { const op = "daemon.newSearchHandlerFunc" switch { case util.IsNil(repo): return nil, errors.New(ctx, errors.InvalidParameter, op, "repository is missing") + case util.IsNil(logger): + return nil, errors.New(ctx, errors.InvalidParameter, op, "logger is missing") case util.IsNil(refreshService): return nil, errors.New(ctx, errors.InvalidParameter, op, "refresh service is missing") } @@ -48,36 +51,46 @@ func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshSe } return func(w http.ResponseWriter, r *http.Request) { - ctx := r.Context() + reqCtx := r.Context() resource := r.URL.Query().Get(resourceKey) authTokenId := r.URL.Query().Get(authTokenIdKey) searchableResource := cache.ToSearchableResource(resource) switch { case resource == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, "resource is a required field but was empty")) writeError(w, "resource is a required field but was empty", http.StatusBadRequest) return case !searchableResource.Valid(): + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, fmt.Sprintf("provided resource %q is not a valid searchable resource", resource))) writeError(w, "provided resource is not a valid searchable resource", http.StatusBadRequest) return case authTokenId == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, fmt.Sprintf("%s is a required field but was empty", authTokenIdKey))) writeError(w, fmt.Sprintf("%s is a required field but was empty", authTokenIdKey), http.StatusBadRequest) return } - t, err := repo.LookupToken(ctx, authTokenId, cache.WithUpdateLastAccessedTime(true)) + t, err := repo.LookupToken(reqCtx, authTokenId, cache.WithUpdateLastAccessedTime(true)) if err != nil || t == nil { + if err != nil { + event.WriteError(ctx, op, err, event.WithInfoMsg("when looking up the auth token", "auth_token_id", authTokenId)) + } + if t == nil { + event.WriteError(ctx, op, errors.New(ctx, errors.NotFound, op, fmt.Sprintf("auth token with id %q not found in cache", authTokenId))) + } writeError(w, "Forbidden", http.StatusForbidden) return } - supported, err := s.Supported(ctx, t) + supported, err := s.Supported(reqCtx, t) if err != nil { event.WriteError(ctx, op, err, event.WithInfoMsg("when checking if search is supported for the provided auth token", "auth_token_id", authTokenId)) writeError(w, err.Error(), http.StatusInternalServerError) return } if !supported { + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, fmt.Sprintf("search not supported for the provided auth token %q", authTokenId))) writeUnsupportedError(w) return } @@ -90,7 +103,7 @@ func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshSe // Refresh the resources for the provided user, if possible. This is best // effort, so if there is any problem refreshing, we just log the error // and move on to handling the search request. - if err := refreshService.RefreshForSearch(ctx, authTokenId, searchableResource, opts...); err != nil { + if err := refreshService.RefreshForSearch(reqCtx, authTokenId, searchableResource, opts...); err != nil { // we don't stop the search, we just log that the inline refresh failed event.WriteError(ctx, op, err, event.WithInfoMsg("when refreshing the resources inline for search", "auth_token_id", authTokenId, "resource", searchableResource)) } @@ -98,13 +111,14 @@ func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshSe query := r.URL.Query().Get(queryKey) filter := r.URL.Query().Get(filterKey) - res, err := s.Search(ctx, cache.SearchParams{ + res, err := s.Search(reqCtx, cache.SearchParams{ AuthTokenId: authTokenId, Resource: searchableResource, Query: query, Filter: filter, }) if err != nil { + event.WriteError(ctx, op, err, event.WithInfoMsg("when performing search", "auth_token_id", authTokenId, "resource", searchableResource, "query", query, "filter", filter)) switch { case errors.Match(errors.T(errors.InvalidParameter), err): writeError(w, err.Error(), http.StatusBadRequest) @@ -121,6 +135,7 @@ func newSearchHandlerFunc(ctx context.Context, repo *cache.Repository, refreshSe apiRes := toApiResult(res) j, err := json.Marshal(apiRes) if err != nil { + event.WriteError(ctx, op, err, event.WithInfoMsg("when marshaling search result to JSON", "auth_token_id", authTokenId, "resource", searchableResource, "query", query, "filter", filter)) writeError(w, err.Error(), http.StatusInternalServerError) return } diff --git a/internal/clientcache/internal/daemon/server.go b/internal/clientcache/internal/daemon/server.go index 73af030a1..81aa8aaa8 100644 --- a/internal/clientcache/internal/daemon/server.go +++ b/internal/clientcache/internal/daemon/server.go @@ -11,7 +11,6 @@ import ( "net/http" "os" "sort" - "strconv" "strings" "sync" "sync/atomic" @@ -59,6 +58,8 @@ type ClientProvider interface { type CacheServer struct { conf *Config + logger hclog.Logger + infoKeys []string info map[string]string @@ -76,7 +77,6 @@ type Config struct { RefreshInterval time.Duration RecheckSupportInterval time.Duration DatabaseUrl string - StoreDebug bool LogLevel string LogFormat string LogWriter io.Writer @@ -123,9 +123,11 @@ func New(ctx context.Context, conf *Config) (*CacheServer, error) { tickerWg: new(sync.WaitGroup), shutdownOnce: new(sync.Once), } - if err := s.setupLogging(ctx, conf.LogWriter); err != nil { + logger, err := s.setupLogging(ctx, conf.LogWriter) + if err != nil { return nil, errors.Wrap(ctx, err, op) } + s.logger = logger return s, nil } @@ -222,18 +224,17 @@ func (s *CacheServer) Serve(ctx context.Context, cmd Commander, opt ...Option) e s.info["Listening address"] = l.Addr().String() s.infoKeys = append(s.infoKeys, "Listening address") - s.info["Store debug"] = strconv.FormatBool(s.conf.StoreDebug) - s.infoKeys = append(s.infoKeys, "Store debug") var store *db.DB - store, s.storeUrl, err = openStore(ctx, s.conf.DatabaseUrl, s.conf.StoreDebug) + store, err = openStore(ctx, + WithUrl(ctx, s.conf.DatabaseUrl), + WithLogger(ctx, s.logger)) if err != nil { return errors.Wrap(ctx, err, op) } s.store.Store(store) - - if s.storeUrl != "" { - s.info["Database URL"] = s.storeUrl + if s.conf.DatabaseUrl != "" { + s.info["Database URL"] = s.conf.DatabaseUrl s.infoKeys = append(s.infoKeys, "Database URL") } maxSearchRefreshTimeout := DefaultSearchRefreshTimeout @@ -270,7 +271,7 @@ func (s *CacheServer) Serve(ctx context.Context, cmd Commander, opt ...Option) e return errors.Wrap(ctx, err, op) } - refreshService, err := cache.NewRefreshService(ctx, repo, maxSearchStaleness, maxSearchRefreshTimeout) + refreshService, err := cache.NewRefreshService(ctx, repo, s.logger, maxSearchStaleness, maxSearchRefreshTimeout) if err != nil { return errors.Wrap(ctx, err, op) } @@ -293,7 +294,7 @@ func (s *CacheServer) Serve(ctx context.Context, cmd Commander, opt ...Option) e }() mux := http.NewServeMux() - searchFn, err := newSearchHandlerFunc(ctx, repo, refreshService) + searchFn, err := newSearchHandlerFunc(ctx, repo, refreshService, s.logger) if err != nil { return errors.Wrap(ctx, err, op) } @@ -311,7 +312,7 @@ func (s *CacheServer) Serve(ctx context.Context, cmd Commander, opt ...Option) e } mux.Handle("/v1/log", serverMetadataInterceptor(logHandlerFn, s.conf.RunningInBackground)) - tokenFn, err := newTokenHandlerFunc(ctx, repo, tic) + tokenFn, err := newTokenHandlerFunc(ctx, repo, tic, s.logger) if err != nil { return errors.Wrap(ctx, err, op) } @@ -389,11 +390,11 @@ func (s *CacheServer) printInfo(ctx context.Context) { event.WriteSysEvent(ctx, op, strings.Join(output, "\n")) } -func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) error { +func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) (hclog.Logger, error) { const op = "daemon.(Command).setupLogging" switch { case util.IsNil(w): - return errors.New(ctx, errors.InvalidParameter, op, "log writer is nil") + return nil, errors.New(ctx, errors.InvalidParameter, op, "log writer is nil") } logFormat := logging.StandardFormat @@ -401,7 +402,7 @@ func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) error { var err error logFormat, err = logging.ParseLogFormat(s.conf.LogFormat) if err != nil { - return fmt.Errorf("%s: %w", op, err) + return nil, fmt.Errorf("%s: %w", op, err) } } @@ -425,7 +426,7 @@ func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) error { case "err", "error": level = hclog.Error default: - return fmt.Errorf("%s: unknown log level: %s", op, logLevel) + return nil, fmt.Errorf("%s: unknown log level: %s", op, logLevel) } var logLock sync.Mutex logger := hclog.New(&hclog.LoggerOptions{ @@ -435,7 +436,7 @@ func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) error { Mutex: &logLock, }) if err := event.InitFallbackLogger(logger); err != nil { - return fmt.Errorf("%s: %w", op, err) + return nil, fmt.Errorf("%s: %w", op, err) } s.info["log level"] = level.String() @@ -445,10 +446,10 @@ func (s *CacheServer) setupLogging(ctx context.Context, w io.Writer) error { var err error if err = setupEventing(ctx, logger, &logLock, logFormat, w); err != nil { - return errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op) } - return nil + return logger, nil } func setupEventing(ctx context.Context, logger hclog.Logger, serializationLock *sync.Mutex, logFormat logging.LogFormat, w io.Writer) error { @@ -495,21 +496,28 @@ func setupEventing(ctx context.Context, logger hclog.Logger, serializationLock * return nil } -func openStore(ctx context.Context, url string, flagDebugStore bool) (*db.DB, string, error) { +func openStore(ctx context.Context, opt ...Option) (*db.DB, error) { const op = "daemon.openStore" - var err error - opts := []cachedb.Option{cachedb.WithDebug(flagDebugStore)} - switch { - case url != "": - url, err = parseutil.ParsePath(url) - if err != nil && !errors.Is(err, parseutil.ErrNotAUrl) { - return nil, "", errors.Wrap(ctx, err, op) - } - opts = append(opts, cachedb.WithUrl(url)) - } - store, err := cachedb.Open(ctx, opts...) + opts, err := getOpts(opt...) if err != nil { - return nil, "", errors.Wrap(ctx, err, op) + return nil, errors.Wrap(ctx, err, op) } - return store, url, nil + + var dbOpts []cachedb.Option + switch { + case opts.withUrl != "": + url, err := parseutil.ParsePath(opts.withUrl) + if err != nil && !errors.Is(err, parseutil.ErrNotAUrl) { + return nil, errors.Wrap(ctx, err, op) + } + dbOpts = append(dbOpts, cachedb.WithUrl(url)) + } + if !util.IsNil(opts.withLogger) { + dbOpts = append(dbOpts, cachedb.WithGormFormatter(opts.withLogger)) + } + store, err := cachedb.Open(ctx, dbOpts...) + if err != nil { + return nil, errors.Wrap(ctx, err, op) + } + return store, nil } diff --git a/internal/clientcache/internal/daemon/testing.go b/internal/clientcache/internal/daemon/testing.go index f185e5bd1..f7db5c001 100644 --- a/internal/clientcache/internal/daemon/testing.go +++ b/internal/clientcache/internal/daemon/testing.go @@ -13,6 +13,7 @@ import ( "github.com/hashicorp/boundary/api/sessions" "github.com/hashicorp/boundary/api/targets" "github.com/hashicorp/boundary/internal/clientcache/internal/cache" + "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/require" ) @@ -27,16 +28,12 @@ type TestServer struct { func NewTestServer(t *testing.T, cmd Commander, opt ...Option) *TestServer { t.Helper() ctx, cancel := context.WithCancel(context.Background()) - - opts, err := getOpts(opt...) - require.NoError(t, err) dotDir := t.TempDir() cfg := &Config{ ContextCancel: cancel, RefreshInterval: DefaultRefreshInterval, RecheckSupportInterval: DefaultRecheckSupportInterval, - StoreDebug: opts.withDebug, LogWriter: io.Discard, DotDirectory: dotDir, } @@ -101,7 +98,7 @@ func (s *TestServer) AddResources(t *testing.T, p *authtokens.AuthToken, tars [] } return sess, nil, "addedsessions", nil } - rs, err := cache.NewRefreshService(ctx, r, 0, 0) + rs, err := cache.NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) require.NoError(t, rs.Refresh(ctx, cache.WithTargetRetrievalFunc(tarFn), cache.WithSessionRetrievalFunc(sessFn))) } @@ -130,7 +127,7 @@ func (s *TestServer) AddUnsupportedCachingData(t *testing.T, p *authtokens.AuthT } return []*sessions.Session{}, nil, "", cache.ErrRefreshNotSupported } - rs, err := cache.NewRefreshService(ctx, r, 0, 0) + rs, err := cache.NewRefreshService(ctx, r, hclog.NewNullLogger(), 0, 0) require.NoError(t, err) err = rs.Refresh(ctx, cache.WithTargetRetrievalFunc(tarFn), cache.WithSessionRetrievalFunc(sessFn)) require.ErrorContains(t, err, "not supported for this controller") diff --git a/internal/clientcache/internal/daemon/token_handler.go b/internal/clientcache/internal/daemon/token_handler.go index a1a57b432..c39aba854 100644 --- a/internal/clientcache/internal/daemon/token_handler.go +++ b/internal/clientcache/internal/daemon/token_handler.go @@ -16,8 +16,11 @@ import ( "github.com/hashicorp/boundary/internal/errors" "github.com/hashicorp/boundary/internal/event" "github.com/hashicorp/boundary/internal/util" + "github.com/hashicorp/go-hclog" ) +const redactedString = "/*redacted*/" + type refresher interface { refresh() } @@ -44,16 +47,38 @@ type UpsertTokenRequest struct { Keyring *KeyringToken `json:"keyring,omitempty"` } -func newTokenHandlerFunc(ctx context.Context, repo *cache.Repository, refresher refresher) (http.HandlerFunc, error) { - const op = "daemon.newPersonaHandlerFunc" +func (u *UpsertTokenRequest) String() string { + if u == nil { + return "nil" + } + out := fmt.Sprintf("BoundaryAddr: %q, AuthTokenId: %q", u.BoundaryAddr, u.AuthTokenId) + if u.Keyring != nil { + out = fmt.Sprintf("%s, Keyring: %+v", out, *u.Keyring) + } + if len(u.AuthToken) > 0 { + // Don't print out the auth token string, but do indicate if it has the + // same prefix as the provided auth token id. + redactedAuthTokenStr := redactedString + if strings.HasPrefix(u.AuthToken, u.AuthTokenId) { + redactedAuthTokenStr = fmt.Sprintf("%s_%s", u.AuthTokenId, redactedAuthTokenStr) + } + out = fmt.Sprintf("%s, AuthToken: %q", out, redactedAuthTokenStr) + } + return out +} + +func newTokenHandlerFunc(ctx context.Context, repo *cache.Repository, refresher refresher, logger hclog.Logger) (http.HandlerFunc, error) { + const op = "daemon.newTokenHandlerFunc" switch { case util.IsNil(repo): return nil, errors.New(ctx, errors.InvalidParameter, op, "repository is nil") + case util.IsNil(logger): + return nil, errors.New(ctx, errors.InvalidParameter, op, "logger is nil") case util.IsNil(refresher): return nil, errors.New(ctx, errors.InvalidParameter, op, "refresher is nil") } return func(w http.ResponseWriter, r *http.Request) { - ctx := r.Context() + reqCtx := r.Context() if r.Method != http.MethodPost { writeError(w, "method not allowed", http.StatusMethodNotAllowed) @@ -70,39 +95,48 @@ func newTokenHandlerFunc(ctx context.Context, repo *cache.Repository, refresher writeError(w, "unable to parse request body", http.StatusBadRequest) return } + logger.Debug("received add-token request", "request", perReq.String()) switch { case perReq.BoundaryAddr == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, "boundary_addr is a required field but was empty"), event.WithInfo("request", perReq.String())) writeError(w, "boundary_addr is a required field but was empty", http.StatusBadRequest) return case perReq.AuthTokenId == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, "auth_token_id is a required field but was empty"), event.WithInfo("request", perReq.String())) writeError(w, "auth_token_id is a required field but was empty", http.StatusBadRequest) return case perReq.Keyring == nil && perReq.AuthToken == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, "either keyring info or the auth_token must be provided but were empty"), event.WithInfo("request", perReq.String())) writeError(w, "Either keyring info or the auth_token must be provided but were empty", http.StatusBadRequest) return case perReq.Keyring != nil: switch { case perReq.Keyring.TokenName == "": + event.WriteError(ctx, op, errors.New(ctx, errors.InvalidParameter, op, "keyring.token_name is a required field but was empty"), event.WithInfo("request", perReq.String())) writeError(w, "keyring.token_name is a required field but was empty", http.StatusBadRequest) return case perReq.Keyring.KeyringType == "": + event.WriteError(reqCtx, op, errors.New(reqCtx, errors.InvalidParameter, op, "keyring.keyring_type is a required field but was empty"), event.WithInfo("request", perReq.String())) writeError(w, "keyring.keyring_type is a required field but was empty", http.StatusBadRequest) return case perReq.Keyring.KeyringType == base.NoneKeyring: + event.WriteError(reqCtx, op, errors.New(reqCtx, errors.InvalidParameter, op, "keyring.keyring_type is set to none which is not supported"), event.WithInfo("request", perReq.String())) writeError(w, fmt.Sprintf("keyring.keyring_type is set to %s which is not supported", perReq.Keyring.KeyringType), http.StatusBadRequest) return } case perReq.AuthToken != "": switch { case !strings.HasPrefix(perReq.AuthToken, perReq.AuthTokenId): + event.WriteError(reqCtx, op, errors.New(reqCtx, errors.InvalidParameter, op, "auth_token_id doesn't match the auth_token's prefix"), event.WithInfo("request", perReq.String())) writeError(w, "auth_token_id doesn't match the auth_token's prefix", http.StatusBadRequest) return } } - oldTok, err := repo.LookupToken(ctx, perReq.AuthTokenId) + oldTok, err := repo.LookupToken(reqCtx, perReq.AuthTokenId) if err != nil { + event.WriteError(reqCtx, op, err, event.WithInfoMsg("error when trying to look up existing cached auth token", "request", perReq.String())) writeError(w, "error performing auth token lookup", http.StatusInternalServerError) return } @@ -114,33 +148,34 @@ func newTokenHandlerFunc(ctx context.Context, repo *cache.Repository, refresher TokenName: perReq.Keyring.TokenName, AuthTokenId: perReq.AuthTokenId, } - if err = repo.AddKeyringToken(ctx, perReq.BoundaryAddr, kt); err != nil { + if err = repo.AddKeyringToken(reqCtx, perReq.BoundaryAddr, kt); err != nil { errCode := http.StatusInternalServerError if errors.Match(errors.T(errors.Forbidden), err) { errCode = http.StatusForbidden } err := fmt.Errorf("Failed to add a keyring stored token with id %q: %w", perReq.AuthTokenId, err) - event.WriteError(ctx, op, err) + event.WriteError(reqCtx, op, err, event.WithInfo("request", perReq.String())) writeError(w, err.Error(), errCode) return } case perReq.AuthToken != "": - if err = repo.AddRawToken(ctx, perReq.BoundaryAddr, perReq.AuthToken); err != nil { + if err = repo.AddRawToken(reqCtx, perReq.BoundaryAddr, perReq.AuthToken); err != nil { errCode := http.StatusInternalServerError if errors.Match(errors.T(errors.Forbidden), err) { errCode = http.StatusForbidden } err := fmt.Errorf("Failed to add a raw token with id %q: %w", perReq.AuthTokenId, err) - event.WriteError(ctx, op, err) + event.WriteError(reqCtx, op, err, event.WithInfo("request", perReq.String())) writeError(w, err.Error(), errCode) return } } - newTok, err := repo.LookupToken(ctx, perReq.AuthTokenId) + newTok, err := repo.LookupToken(reqCtx, perReq.AuthTokenId) if err != nil { + event.WriteError(reqCtx, op, err, event.WithInfoMsg("error when trying to look up newly added cached auth token", "request", perReq.String())) writeError(w, "error performing follow up auth token lookup", http.StatusInternalServerError) return } @@ -148,6 +183,7 @@ func newTokenHandlerFunc(ctx context.Context, repo *cache.Repository, refresher w.WriteHeader(http.StatusNoContent) if oldTok == nil && newTok != nil { + logger.Debug("New auth token added to the cache. Initiating a cache refresh.", "request", perReq.String()) refresher.refresh() } }, nil diff --git a/internal/clientcache/internal/daemon/token_handler_test.go b/internal/clientcache/internal/daemon/token_handler_test.go index f7fe57bbc..b6bcbdaeb 100644 --- a/internal/clientcache/internal/daemon/token_handler_test.go +++ b/internal/clientcache/internal/daemon/token_handler_test.go @@ -18,6 +18,7 @@ import ( "github.com/hashicorp/boundary/internal/clientcache/internal/cache" cachedb "github.com/hashicorp/boundary/internal/clientcache/internal/db" "github.com/hashicorp/boundary/internal/cmd/base" + "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -94,7 +95,7 @@ func TestKeyringToken(t *testing.T) { require.NoError(t, err) tr := &testRefresher{} - ph, err := newTokenHandlerFunc(ctx, r, tr) + ph, err := newTokenHandlerFunc(ctx, r, tr, hclog.NewNullLogger()) require.NoError(t, err) t.Run("missing keyring", func(t *testing.T) { @@ -223,7 +224,7 @@ func TestKeyringlessToken(t *testing.T) { require.NoError(t, err) tr := &testRefresher{} - ph, err := newTokenHandlerFunc(ctx, r, tr) + ph, err := newTokenHandlerFunc(ctx, r, tr, hclog.NewNullLogger()) require.NoError(t, err) t.Run("missing boundary address", func(t *testing.T) { @@ -278,3 +279,49 @@ func TestKeyringlessToken(t *testing.T) { assert.Equal(t, at.Id, p.Id) }) } + +func TestUpsertTokenRequest_String(t *testing.T) { + cases := []struct { + name string + req *UpsertTokenRequest + want string + }{ + { + name: "auth token fully redacted", + req: &UpsertTokenRequest{ + BoundaryAddr: "test", + AuthToken: "at_wrong_SomethingElseHere", + AuthTokenId: "at_prefix", + }, + want: "BoundaryAddr: \"test\", AuthTokenId: \"at_prefix\", AuthToken: \"/*redacted*/\"", + }, + { + name: "auth token partially redacted", + req: &UpsertTokenRequest{ + BoundaryAddr: "test", + AuthToken: "at_prefix_SomethingElseHere", + AuthTokenId: "at_prefix", + }, + want: "BoundaryAddr: \"test\", AuthTokenId: \"at_prefix\", AuthToken: \"at_prefix_/*redacted*/\"", + }, + { + name: "auth token partially redacted", + req: &UpsertTokenRequest{ + BoundaryAddr: "test", + Keyring: &KeyringToken{ + TokenName: "token", + KeyringType: "type", + }, + AuthToken: "at_prefix_SomethingElseHere", + AuthTokenId: "at_prefix", + }, + want: "BoundaryAddr: \"test\", AuthTokenId: \"at_prefix\", Keyring: {KeyringType:type TokenName:token}, AuthToken: \"at_prefix_/*redacted*/\"", + }, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + assert.Equal(t, tc.want, tc.req.String()) + }) + } +} diff --git a/internal/clientcache/internal/db/db.go b/internal/clientcache/internal/db/db.go index f4fc3de74..31907a3b0 100644 --- a/internal/clientcache/internal/db/db.go +++ b/internal/clientcache/internal/db/db.go @@ -10,6 +10,7 @@ import ( "github.com/hashicorp/boundary/internal/db" "github.com/hashicorp/boundary/internal/errors" + "github.com/hashicorp/boundary/internal/util" "github.com/hashicorp/go-dbw" ) @@ -34,9 +35,15 @@ func Open(ctx context.Context, opt ...Option) (*db.DB, error) { default: url = DefaultStoreUrl } + + dbOpts := []db.Option{db.WithMaxOpenConnections(1)} + if !util.IsNil(opts.withGormFormatter) { + dbOpts = append(dbOpts, db.WithGormFormatter(opts.withGormFormatter)) + } + // sqlite db must be set to 1 max open connection so requests can be serialized // otherwise reading while a tx is ongoing results in sql logic errors. - conn, err := db.Open(ctx, db.Sqlite, url, db.WithMaxOpenConnections(1)) + conn, err := db.Open(ctx, db.Sqlite, url, dbOpts...) if err != nil { return nil, errors.Wrap(ctx, err, op) } diff --git a/internal/clientcache/internal/db/options.go b/internal/clientcache/internal/db/options.go index a44c62292..ba8c3382b 100644 --- a/internal/clientcache/internal/db/options.go +++ b/internal/clientcache/internal/db/options.go @@ -5,12 +5,14 @@ package db import ( "github.com/hashicorp/go-dbw" + "github.com/hashicorp/go-hclog" ) type options struct { - withDebug bool - withUrl string - withDbType dbw.DbType + withDebug bool + withUrl string + withDbType dbw.DbType + withGormFormatter hclog.Logger } // Option - how options are passed as args @@ -33,6 +35,13 @@ func getOpts(opt ...Option) (options, error) { return opts, nil } +func WithGormFormatter(logger hclog.Logger) Option { + return func(o *options) error { + o.withGormFormatter = logger + return nil + } +} + // WithUrls provides optional url func WithUrl(url string) Option { return func(o *options) error {