Skip to content

Commit

Permalink
Add Error logging and hclog.Logger debug logging throughout the daemon (
Browse files Browse the repository at this point in the history 
#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
  • Loading branch information
@talanknight
talanknight authored Feb 22, 2024
1 parent 014a5a7 commit 366d9e9
Show file tree
Hide file tree
Showing 14 changed files with 294 additions and 143 deletions.
12 changes: 6 additions & 6 deletions internal/clientcache/cmd/daemon/start.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -191,14 +191,17 @@ 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,
RecheckSupportInterval: c.flagRecheckSupportInterval,
MaxSearchStaleness: c.flagMaxSearchStaleness,
MaxSearchRefreshTimeout: c.flagMaxSearchRefreshTimeout,
DatabaseUrl: c.flagDatabaseUrl,
StoreDebug: c.flagStoreDebug,
LogLevel: c.flagLogLevel,
LogFormat: c.flagLogFormat,
LogWriter: io.MultiWriter(writers...),
Expand Down Expand Up @@ -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 {
Expand Down
61 changes: 36 additions & 25 deletions internal/clientcache/internal/cache/refresh.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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
Expand Down Expand Up @@ -66,18 +72,19 @@ 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)
var apiErr *api.Error
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
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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) {
Expand All @@ -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:
Expand All @@ -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
Expand All @@ -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
}

Expand All @@ -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 {
Expand All @@ -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 {
Expand Down
29 changes: 15 additions & 14 deletions internal/clientcache/internal/cache/refresh_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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) {
Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down Expand Up @@ -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}))

Expand Down
Loading

0 comments on commit 366d9e9

Please sign in to comment.