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/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 {

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) {

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
 		}

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
 }

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")

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

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())
+		})
+	}
+}