diff --git a/internal/cmd/base/dev.go b/internal/cmd/base/dev.go index 4059eb934..a4553845a 100644 --- a/internal/cmd/base/dev.go +++ b/internal/cmd/base/dev.go @@ -14,12 +14,14 @@ import ( "github.com/hashicorp/boundary/internal/docker" "github.com/hashicorp/boundary/internal/iam" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/types/scope" capoidc "github.com/hashicorp/cap/oidc" "github.com/hashicorp/go-multierror" ) func (b *Server) CreateDevDatabase(ctx context.Context, opt ...Option) error { + const op = "base.(Server).CreateDevDatabase" var container, url, dialect string var err error var c func() error @@ -29,7 +31,7 @@ func (b *Server) CreateDevDatabase(ctx context.Context, opt ...Option) error { // We should only get back postgres for now, but laying the foundation for non-postgres switch opts.withDialect { case "": - b.Logger.Error("unsupported dialect. wanted: postgres, got: %v", opts.withDialect) + event.WriteError(ctx, op, err, event.WithInfoMsg("unsupported dialect", "wanted", "postgres", "got", opts.withDialect)) default: dialect = opts.withDialect } @@ -43,7 +45,7 @@ func (b *Server) CreateDevDatabase(ctx context.Context, opt ...Option) error { if !opts.withSkipDatabaseDestruction { if c != nil { if err := c(); err != nil { - b.Logger.Error("error cleaning up docker container", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error cleaning up docker container")) } } } diff --git a/internal/cmd/base/servers.go b/internal/cmd/base/servers.go index 8bb239c36..443fc4797 100644 --- a/internal/cmd/base/servers.go +++ b/internal/cmd/base/servers.go @@ -259,8 +259,12 @@ func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, confi // logic and re-enable. /* proxyCfg := httpproxy.FromEnvironment() - b.Logger.Info("proxy environment", "http_proxy", proxyCfg.HTTPProxy, - "https_proxy", proxyCfg.HTTPSProxy, "no_proxy", proxyCfg.NoProxy) + event.WriteSysEvent(context.TODO(), op, + "proxy environment", + "http_proxy", proxyCfg.HTTPProxy, + "https_proxy", proxyCfg.HTTPSProxy, + "no_proxy", proxyCfg.NoProxy, + }) */ // Setup gorm logging @@ -716,6 +720,8 @@ func MakeSighupCh() chan struct{} { // The minimum setting for this value is the default setting. Values // below this will be reset to the default. func (s *Server) SetStatusGracePeriodDuration(value time.Duration) { + const op = "base.(Server).SetStatusGracePeriodDuration" + ctx := context.TODO() var result time.Duration switch { case value > 0: @@ -726,10 +732,7 @@ func (s *Server) SetStatusGracePeriodDuration(value time.Duration) { v := os.Getenv(statusGracePeriodEnvVar) n, err := strconv.Atoi(v) if err != nil { - s.Logger.Error(fmt.Sprintf("could not read setting for %s", statusGracePeriodEnvVar), - "err", err, - "value", v, - ) + event.WriteError(ctx, op, err, event.WithInfoMsg("could not read status grace period setting", "envvar", statusGracePeriodEnvVar, "value", v)) break } @@ -737,10 +740,8 @@ func (s *Server) SetStatusGracePeriodDuration(value time.Duration) { } if result < defaultStatusGracePeriod { - s.Logger.Debug("invalid grace period setting or none provided, using default", "value", result, "default", defaultStatusGracePeriod) result = defaultStatusGracePeriod } - s.Logger.Debug("session cleanup in effect, connections will be terminated if status reports cannot be made", "grace_period", result) s.StatusGracePeriodDuration = result } diff --git a/internal/cmd/commands/dev/dev.go b/internal/cmd/commands/dev/dev.go index fb0b229ab..a4b663f9a 100644 --- a/internal/cmd/commands/dev/dev.go +++ b/internal/cmd/commands/dev/dev.go @@ -1,6 +1,7 @@ package dev import ( + "context" "errors" "fmt" "net" @@ -316,6 +317,7 @@ func (c *Command) AutocompleteFlags() complete.Flags { } func (c *Command) Run(args []string) int { + const op = "dev.(Command).Run" c.CombineLogs = c.flagCombineLogs var err error @@ -641,7 +643,7 @@ func (c *Command) Run(args []string) int { case <-c.SigUSR2Ch: buf := make([]byte, 32*1024*1024) n := runtime.Stack(buf[:], true) - c.Logger.Info("goroutine trace", "stack", string(buf[:n])) + event.WriteSysEvent(context.TODO(), op, "goroutine trace", "stack", string(buf[:n])) } } diff --git a/internal/cmd/commands/server/server.go b/internal/cmd/commands/server/server.go index fd4b72ab7..7c9a8b3c1 100644 --- a/internal/cmd/commands/server/server.go +++ b/internal/cmd/commands/server/server.go @@ -2,6 +2,7 @@ package server import ( "context" + stderrors "errors" "fmt" "net" "runtime" @@ -15,6 +16,7 @@ import ( "github.com/hashicorp/boundary/internal/db/schema" "github.com/hashicorp/boundary/internal/errors" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers/controller" "github.com/hashicorp/boundary/internal/servers/worker" "github.com/hashicorp/boundary/internal/types/scope" @@ -583,6 +585,7 @@ func (c *Command) StartWorker() error { } func (c *Command) WaitForInterrupt() int { + const op = "server.(Command).WaitForInterrupt" // Wait for shutdown shutdownTriggered := false @@ -623,13 +626,13 @@ func (c *Command) WaitForInterrupt() int { newConf, err = config.LoadFile(c.flagConfig, c.configWrapper) } if err != nil { - c.Logger.Error("could not reload config", "path", c.flagConfig, "error", err) + event.WriteError(context.TODO(), op, err, event.WithInfoMsg("could not reload config", "path", c.flagConfig)) goto RUNRELOADFUNCS } // Ensure at least one config was found. if newConf == nil { - c.Logger.Error("no config found at reload time") + event.WriteError(context.TODO(), op, stderrors.New("no config found at reload time")) goto RUNRELOADFUNCS } @@ -647,7 +650,7 @@ func (c *Command) WaitForInterrupt() int { case "err", "error": level = hclog.Error default: - c.Logger.Error("unknown log level found on reload", "level", newConf.LogLevel) + event.WriteError(context.TODO(), op, stderrors.New("unknown log level found on reload"), event.WithInfo("level", newConf.LogLevel)) goto RUNRELOADFUNCS } c.Logger.SetLevel(level) @@ -661,7 +664,7 @@ func (c *Command) WaitForInterrupt() int { case <-c.SigUSR2Ch: buf := make([]byte, 32*1024*1024) n := runtime.Stack(buf[:], true) - c.Logger.Info("goroutine trace", "stack", string(buf[:n])) + event.WriteSysEvent(context.TODO(), op, "goroutine trace", "stack", string(buf[:n])) } } diff --git a/internal/credential/vault/jobs.go b/internal/credential/vault/jobs.go index 54638152d..0f5ddd862 100644 --- a/internal/credential/vault/jobs.go +++ b/internal/credential/vault/jobs.go @@ -8,6 +8,7 @@ import ( "github.com/hashicorp/boundary/internal/db" "github.com/hashicorp/boundary/internal/errors" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/oplog" "github.com/hashicorp/boundary/internal/scheduler" "github.com/hashicorp/go-hclog" @@ -161,7 +162,7 @@ func (r *TokenRenewalJob) Run(ctx context.Context) error { return errors.Wrap(err, op) } if err := r.renewToken(ctx, s); err != nil { - r.logger.Error("error renewing token", "credential store id", s.StoreId, "token status", s.TokenStatus, "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error renewing token", "credential store id", s.StoreId, "token status", s.TokenStatus)) } r.numProcessed++ } @@ -205,7 +206,7 @@ func (r *TokenRenewalJob) renewToken(ctx context.Context, s *privateStore) error return errors.New(errors.Unknown, op, "token expired but failed to update repo") } if s.TokenStatus == string(CurrentToken) { - r.logger.Info("Vault credential store current token has expired", "credential store id", s.StoreId) + event.WriteSysEvent(ctx, op, "Vault credential store current token has expired", "credential store id", s.StoreId) } // Set credentials associated with this token to expired as Vault will already cascade delete them @@ -395,7 +396,7 @@ or return errors.Wrap(err, op) } if err := r.revokeToken(ctx, s); err != nil { - r.logger.Error("error revoking token", "credential store id", s.StoreId, "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error revoking token", "credential store id", s.StoreId)) } r.numProcessed++ } @@ -555,7 +556,7 @@ func (r *CredentialRenewalJob) Run(ctx context.Context) error { } if err := r.renewCred(ctx, c); err != nil { - r.logger.Error("error renewing credential", "credential id", c.PublicId, "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error renewing credential", "credential id", c.PublicId)) } r.numProcessed++ @@ -719,7 +720,7 @@ func (r *CredentialRevocationJob) Run(ctx context.Context) error { return errors.Wrap(err, op) } if err := r.revokeCred(ctx, c); err != nil { - r.logger.Error("error revoking credential", "credential id", c.PublicId, "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error revoking credential", "credential id", c.PublicId)) } r.numProcessed++ } @@ -869,14 +870,14 @@ func (r *CredentialStoreCleanupJob) Run(ctx context.Context) error { oplogWrapper, err := r.kms.GetWrapper(ctx, store.ScopeId, kms.KeyPurposeOplog) if err != nil { - r.logger.Error("unable to get oplog wrapper for credential store cleanup job", "credential store id", store.PublicId) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to get oplog wrapper for credential store cleanup job", "credential store id", store.PublicId)) r.numProcessed++ continue } _, err = r.writer.Delete(ctx, store, db.WithOplog(oplogWrapper, store.oplog(oplog.OpType_OP_TYPE_DELETE))) if err != nil { - r.logger.Error("error deleting credential store", "error", err, "credential store id", store.PublicId) + event.WriteError(ctx, op, err, event.WithInfoMsg("error deleting credential store", "credential store id", store.PublicId)) } r.numProcessed++ diff --git a/internal/db/db.go b/internal/db/db.go index 3ef969a15..d3fd54b57 100644 --- a/internal/db/db.go +++ b/internal/db/db.go @@ -1,11 +1,14 @@ package db import ( + "context" + stderrors "errors" "fmt" "math" "time" "github.com/hashicorp/boundary/internal/docker" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" "github.com/jinzhu/gorm" "github.com/lib/pq" @@ -47,11 +50,15 @@ func Open(dbType DbType, connectionUrl string) (*gorm.DB, error) { } func GetGormLogFormatter(log hclog.Logger) func(values ...interface{}) (messages []interface{}) { + const op = "db.GetGormLogFormatter" + ctx := context.TODO() return func(values ...interface{}) (messages []interface{}) { if len(values) > 2 && values[0].(string) == "log" { switch values[2].(type) { case *pq.Error: - log.Trace("error from database adapter", "location", values[1], "error", values[2]) + if log.IsTrace() { + event.WriteError(ctx, op, stderrors.New("error from database adapter"), event.WithInfo("error", values[2], "location", values[1])) + } } return nil } diff --git a/internal/libs/alpnmux/mux.go b/internal/libs/alpnmux/mux.go index cb54319c4..69d94a413 100644 --- a/internal/libs/alpnmux/mux.go +++ b/internal/libs/alpnmux/mux.go @@ -10,6 +10,7 @@ import ( "strings" "sync" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" ) @@ -80,6 +81,8 @@ func (l *ALPNMux) SetLogger(log hclog.Logger) { } func (l *ALPNMux) RegisterProto(proto string, tlsConf *tls.Config) (net.Listener, error) { + const op = "alpnmux.(ALPNMux).RegisterProto" + ctx := context.TODO() switch proto { case NoProto: if tlsConf != nil { @@ -110,13 +113,15 @@ func (l *ALPNMux) RegisterProto(proto string, tlsConf *tls.Config) (net.Listener } if l.log != nil && l.log.IsDebug() { - l.log.Debug("registered", "proto", proto) + event.WriteSysEvent(ctx, op, "registered", "proto", proto) } return sub, nil } func (l *ALPNMux) UnregisterProto(proto string) { + const op = "alpnmux.(ALPNMux).UnregisterProto" + ctx := context.TODO() val, ok := l.muxMap.Load(proto) if !ok { return @@ -130,7 +135,7 @@ func (l *ALPNMux) UnregisterProto(proto string) { }) l.muxMap.Delete(proto) if l.log != nil && l.log.IsDebug() { - l.log.Debug("unregistered", "proto", proto) + event.WriteSysEvent(ctx, op, "unregistered", "proto", proto) } } @@ -146,10 +151,12 @@ func (l *ALPNMux) GetListener(proto string) net.Listener { } func (l *ALPNMux) getConfigForClient(hello *tls.ClientHelloInfo) (*tls.Config, error) { + const op = "alpnmux.(ALPNMux).getConfigForClient" + ctx := context.TODO() var ret *tls.Config if l.log != nil && l.log.IsTrace() { - l.log.Trace("getting config for client", "supported_protos", hello.SupportedProtos, "server_name", hello.ServerName) + event.WriteSysEvent(ctx, op, "getting config for client", "supported_protos", hello.SupportedProtos, "server_name", hello.ServerName) } supportedProtos := hello.SupportedProtos @@ -182,6 +189,8 @@ func (l *ALPNMux) getConfigForClient(hello *tls.ClientHelloInfo) (*tls.Config, e } func (l *ALPNMux) accept() { + const op = "alpnmux.(ALPNMux).accept" + ctx := context.TODO() baseTLSConf := &tls.Config{ GetConfigForClient: l.getConfigForClient, } @@ -197,7 +206,7 @@ func (l *ALPNMux) accept() { continue } if l.log != nil && l.log.IsTrace() { - l.log.Trace("got connection", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "got connection", "addr", conn.RemoteAddr()) } // Do the rest in a goroutine so that a timeout in e.g. handshaking @@ -210,7 +219,7 @@ func (l *ALPNMux) accept() { peeked, err := bufConn.buffer.Peek(3) if err != nil { if l.log != nil && l.log.IsDebug() { - l.log.Debug("error peeking connection", "addr", conn.RemoteAddr(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error peeking connection", "addr", conn.RemoteAddr())) } bufConn.Close() return @@ -220,18 +229,18 @@ func (l *ALPNMux) accept() { // third can be 3 or 1 depending on the implementation case peeked[0] != 0x16 || peeked[1] != 0x03 || (peeked[2] != 0x03 && peeked[2] != 0x01): if l.log != nil && l.log.IsTrace() { - l.log.Trace("connection is not tls", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "connection is not tls", "addr", conn.RemoteAddr()) } val, ok := l.muxMap.Load(NoProto) if !ok { if l.log != nil && l.log.IsTrace() { - l.log.Trace("no non-tls registration found", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "no non-tls registration found", "addr", conn.RemoteAddr()) } bufConn.Close() return } if l.log != nil && l.log.IsTrace() { - l.log.Trace("found noproto handler", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "found noproto handler", "addr", conn.RemoteAddr()) } ml := val.(*muxedListener) ml.connMutex.RLock() @@ -242,36 +251,36 @@ func (l *ALPNMux) accept() { default: if l.log != nil && l.log.IsTrace() { - l.log.Trace("connection is tls", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "connection is tls", "addr", conn.RemoteAddr()) } tlsConn := tls.Server(bufConn, baseTLSConf) if l.log != nil && l.log.IsTrace() { - l.log.Trace("handshaking", "addr", conn.RemoteAddr()) + event.WriteSysEvent(ctx, op, "handshaking", "addr", conn.RemoteAddr()) } if err := tlsConn.Handshake(); err != nil { closeErr := tlsConn.Close() if l.log != nil && l.log.IsDebug() { - l.log.Debug("error handshaking connection", "addr", conn.RemoteAddr(), "error", err, "close_error", closeErr) + event.WriteError(ctx, op, err, event.WithInfoMsg("error handshaking connection", "addr", conn.RemoteAddr(), "close_error", closeErr)) } return } negProto := tlsConn.ConnectionState().NegotiatedProtocol if l.log != nil && l.log.IsTrace() { - l.log.Trace("tls negotiated", "addr", conn.RemoteAddr(), "proto", negProto) + event.WriteSysEvent(ctx, op, "tls negotiated", "addr", conn.RemoteAddr(), "proto", negProto) } val, ok := l.muxMap.Load(negProto) if !ok { val, ok = l.muxMap.Load(DefaultProto) if !ok { if l.log != nil && l.log.IsTrace() { - l.log.Trace("no handler found", "addr", conn.RemoteAddr(), "proto", negProto) + event.WriteSysEvent(ctx, op, "no handler found", "addr", conn.RemoteAddr(), "proto", negProto) } tlsConn.Close() return } } if l.log != nil && l.log.IsTrace() { - l.log.Trace("found tls handler", "addr", conn.RemoteAddr(), "proto", negProto) + event.WriteSysEvent(ctx, op, "found tls handler", "addr", conn.RemoteAddr(), "proto", negProto) } ml := val.(*muxedListener) ml.connMutex.RLock() diff --git a/internal/libs/alpnmux/mux_test.go b/internal/libs/alpnmux/mux_test.go index b002b227d..782d6fbd8 100644 --- a/internal/libs/alpnmux/mux_test.go +++ b/internal/libs/alpnmux/mux_test.go @@ -10,6 +10,7 @@ import ( "testing" "time" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" "go.uber.org/atomic" ) @@ -65,6 +66,16 @@ func TestRegistrationErrors(t *testing.T) { } func TestListening(t *testing.T) { + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestListening", event.WithEventerConfig(testConfig)) + if err != nil { + t.Fatal(err) + } listener := getListener(t) logger := hclog.Default() diff --git a/internal/observability/event/context.go b/internal/observability/event/context.go index 92bd6c51a..439488c4f 100644 --- a/internal/observability/event/context.go +++ b/internal/observability/event/context.go @@ -6,6 +6,7 @@ import ( "os" "runtime" "strings" + "time" "github.com/hashicorp/boundary/globals" "github.com/hashicorp/go-hclog" @@ -13,6 +14,8 @@ import ( type key int +const cancelledSendTimeout = 3 * time.Second + const ( eventerKey key = iota requestInfoKey @@ -76,11 +79,6 @@ func RequestInfoFromContext(ctx context.Context) (*RequestInfo, bool) { // WithHeader, WithDetails, WithId, WithFlush and WithRequestInfo. All other // options are ignored. func WriteObservation(ctx context.Context, caller Op, opt ...Option) error { - // TODO (jimlambrt) 6/2021: remove this feature flag envvar when events are - // generally available. - if !strings.EqualFold(os.Getenv(globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS), "true") { - return nil - } const op = "event.WriteObservation" if ctx == nil { return fmt.Errorf("%s: missing context: %w", op, ErrInvalidParameter) @@ -109,7 +107,11 @@ func WriteObservation(ctx context.Context, caller Op, opt ...Option) error { if err != nil { return fmt.Errorf("%s: %w", op, err) } - if err := eventer.writeObservation(ctx, e); err != nil { + sendCtx, sendCancel := newSendCtx(ctx) + if sendCancel != nil { + defer sendCancel() + } + if err := eventer.writeObservation(sendCtx, e); err != nil { return fmt.Errorf("%s: %w", op, err) } return nil @@ -119,14 +121,9 @@ func WriteObservation(ctx context.Context, caller Op, opt ...Option) error { // ctx for an eventer, then try event.SysEventer() and if no eventer can be // found an hclog.Logger will be created and used. // -// The options WithId and WithRequestInfo are supported and all other options -// are ignored. +// The options WithInfoMsg, WithInfo, WithId and WithRequestInfo are supported +// and all other options are ignored. func WriteError(ctx context.Context, caller Op, e error, opt ...Option) { - // TODO (jimlambrt) 6/2021: remove this feature flag envvar when events are - // generally available. - if !strings.EqualFold(os.Getenv(globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS), "true") { - return - } const op = "event.WriteError" // EventerFromContext will handle a nil ctx appropriately. If e or caller is // missing, newError(...) will handle them appropriately. @@ -154,7 +151,11 @@ func WriteError(ctx context.Context, caller Op, e error, opt ...Option) { eventer.logger.Error(fmt.Sprintf("%s: unable to create new error to write error: %v", op, e)) return } - if err := eventer.writeError(ctx, ev); err != nil { + sendCtx, sendCancel := newSendCtx(ctx) + if sendCancel != nil { + defer sendCancel() + } + if err := eventer.writeError(sendCtx, ev); err != nil { eventer.logger.Error(fmt.Sprintf("%s: %v", op, err)) eventer.logger.Error(fmt.Sprintf("%s: unable to write error: %v", op, e)) return @@ -199,7 +200,11 @@ func WriteAudit(ctx context.Context, caller Op, opt ...Option) error { if err != nil { return fmt.Errorf("%s: %w", op, err) } - if err := eventer.writeAudit(ctx, e); err != nil { + sendCtx, sendCancel := newSendCtx(ctx) + if sendCancel != nil { + defer sendCancel() + } + if err := eventer.writeAudit(sendCtx, e); err != nil { return fmt.Errorf("%s: %w", op, err) } return nil @@ -216,7 +221,7 @@ func addCtxOptions(ctx context.Context, opt ...Option) ([]Option, error) { // there's no RequestInfo, so there's no id associated with the // event and we'll generate one and flush the event // since there will never be another with the same id - id, err := NewId(idPrefix) + id, err := NewId(IdPrefix) if err != nil { return nil, fmt.Errorf("%s: %w", op, err) } @@ -250,13 +255,22 @@ func addCtxOptions(ctx context.Context, opt ...Option) ([]Option, error) { // WriteSysEvent will write a sysevent using the eventer from // event.SysEventer() if no eventer can be found an hclog.Logger will be created -// and used. This function should never be used when sending events while +// and used. The args are and optional set of key/value pairs about the event. +// +// This function should never be used when sending events while // handling API requests. -func WriteSysEvent(ctx context.Context, caller Op, data map[string]interface{}) { - const op = "event.WriteError" - if data == nil { +func WriteSysEvent(ctx context.Context, caller Op, msg string, args ...interface{}) { + const op = "event.WriteSysEvent" + + info := ConvertArgs(args...) + if msg == "" && info == nil { return } + if info == nil { + info = make(map[string]interface{}, 1) + } + info[msgField] = msg + if caller == "" { pc, _, _, ok := runtime.Caller(1) details := runtime.FuncForPC(pc) @@ -267,28 +281,84 @@ func WriteSysEvent(ctx context.Context, caller Op, data map[string]interface{}) } } - eventer := SysEventer() - if eventer == nil { - logger := hclog.New(nil) - logger.Error(fmt.Sprintf("%s: no eventer available to write sysevent: (%s) %+v", op, caller, data)) - return + eventer, ok := EventerFromContext(ctx) + if !ok { + eventer = SysEventer() + if eventer == nil { + logger := hclog.New(nil) + logger.Error(fmt.Sprintf("%s: no eventer available to write sysevent: (%s) %+v", op, caller, info)) + return + } } id, err := NewId(string(SystemType)) if err != nil { eventer.logger.Error(fmt.Sprintf("%s: %v", op, err)) - eventer.logger.Error(fmt.Sprintf("%s: unable to generate id while writing sysevent: (%s) %+v", op, caller, data)) + eventer.logger.Error(fmt.Sprintf("%s: unable to generate id while writing sysevent: (%s) %+v", op, caller, info)) } e := &sysEvent{ Id: Id(id), Version: sysVersion, Op: caller, - Data: data, + Data: info, } - if err := eventer.writeSysEvent(ctx, e); err != nil { + sendCtx, sendCancel := newSendCtx(ctx) + if sendCancel != nil { + defer sendCancel() + } + if err := eventer.writeSysEvent(sendCtx, e); err != nil { eventer.logger.Error(fmt.Sprintf("%s: %v", op, err)) eventer.logger.Error(fmt.Sprintf("%s: unable to write sysevent: (%s) %+v", op, caller, e)) return } } + +func newSendCtx(ctx context.Context) (context.Context, context.CancelFunc) { + var sendCtx context.Context + var sendCancel context.CancelFunc + switch { + case ctx.Err() == context.Canceled: + sendCtx, sendCancel = context.WithTimeout(context.Background(), cancelledSendTimeout) + info, ok := RequestInfoFromContext(ctx) + if ok { + reqCtx, err := NewRequestInfoContext(sendCtx, info) + if err == nil { + sendCtx = reqCtx + } + } + default: + sendCtx = ctx + } + return sendCtx, sendCancel +} + +// MissingKey defines a key to be used as the "missing key" when ConvertArgs has +// an odd number of args (it's missing a key in its key/value pairs) +const MissingKey = "EXTRA_VALUE_AT_END" + +// ConvertArgs will convert the key/value pair args to a map. If the args +// provided are an odd number (they're missing a key in their key/value pairs) +// then MissingKey is used to the missing key. +func ConvertArgs(args ...interface{}) map[string]interface{} { + if len(args) == 0 { + return nil + } + if len(args)%2 != 0 { + extra := args[len(args)-1] + args = append(args[:len(args)-1], MissingKey, extra) + } + + m := map[string]interface{}{} + for i := 0; i < len(args); i = i + 2 { + var key string + switch st := args[i].(type) { + case string: + key = st + default: + key = fmt.Sprintf("%v", st) + } + m[key] = args[i+1] + } + return m +} diff --git a/internal/observability/event/context_test.go b/internal/observability/event/context_test.go index 96226f8e3..b15545047 100644 --- a/internal/observability/event/context_test.go +++ b/internal/observability/event/context_test.go @@ -3,6 +3,7 @@ package event_test import ( "context" "encoding/json" + stderrors "errors" "fmt" "io/ioutil" "os" @@ -295,25 +296,19 @@ func Test_WriteObservation(t *testing.T) { noEventId.Id = "" type observationPayload struct { - header map[string]interface{} - details map[string]interface{} + header []interface{} + details []interface{} } testPayloads := []observationPayload{ { - header: map[string]interface{}{ - "name": "bar", - }, + header: []interface{}{"name", "bar"}, }, { - header: map[string]interface{}{ - "list": []string{"1", "2"}, - }, + header: []interface{}{"list", []string{"1", "2"}}, }, { - details: map[string]interface{}{ - "file": "temp-file.txt", - }, + details: []interface{}{"file", "temp-file.txt"}, }, } @@ -346,9 +341,7 @@ func Test_WriteObservation(t *testing.T) { ctx: testCtxNoEventInfoId, observationPayload: []observationPayload{ { - header: map[string]interface{}{ - "name": "bar", - }, + header: []interface{}{"name", "bar"}, }, }, header: map[string]interface{}{ @@ -397,9 +390,29 @@ func Test_WriteObservation(t *testing.T) { ctx: context.Background(), observationPayload: []observationPayload{ { - header: map[string]interface{}{ - "name": "bar", - }, + header: []interface{}{"name", "bar"}, + }, + }, + header: map[string]interface{}{ + "name": "bar", + }, + observationSinkFileName: c.AllEvents.Name(), + setup: func() error { + return event.InitSysEventer(testLogger, testLock, "use-syseventer", event.WithEventerConfig(&c.EventerConfig)) + }, + cleanup: func() { event.TestResetSystEventer(t) }, + }, + { + name: "use-syseventer-with-cancelled-ctx", + noFlush: true, + ctx: func() context.Context { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + return ctx + }(), + observationPayload: []observationPayload{ + { + header: []interface{}{"name", "bar"}, }, }, header: map[string]interface{}{ @@ -435,7 +448,7 @@ func Test_WriteObservation(t *testing.T) { } require.Greater(len(tt.observationPayload), 0) for _, p := range tt.observationPayload { - err := event.WriteObservation(tt.ctx, event.Op(op), event.WithHeader(p.header), event.WithDetails(p.details)) + err := event.WriteObservation(tt.ctx, event.Op(op), event.WithHeader(p.header...), event.WithDetails(p.details...)) if tt.wantErrIs != nil { assert.ErrorIs(err, tt.wantErrIs) if tt.wantErrContains != "" { @@ -507,39 +520,31 @@ func Test_Filtering(t *testing.T) { name string allow []string deny []string - hdr map[string]interface{} + hdr []interface{} found bool }{ { name: "allowed", allow: []string{`"/Data/list" contains "1"`}, - hdr: map[string]interface{}{ - "list": []string{"1", "2"}, - }, + hdr: []interface{}{"list", []string{"1", "2"}}, found: true, }, { name: "not-allowed", allow: []string{`"/Data/list" contains "22"`}, - hdr: map[string]interface{}{ - "list": []string{"1", "2"}, - }, + hdr: []interface{}{"list", []string{"1", "2"}}, found: false, }, { - name: "deny", - deny: []string{`"/Data/list" contains "1"`}, - hdr: map[string]interface{}{ - "list": []string{"1", "2"}, - }, + name: "deny", + deny: []string{`"/Data/list" contains "1"`}, + hdr: []interface{}{"list", []string{"1", "2"}}, found: false, }, { - name: "not-deny", - deny: []string{`"/Data/list" contains "22"`}, - hdr: map[string]interface{}{ - "list": []string{"1", "2"}, - }, + name: "not-deny", + deny: []string{`"/Data/list" contains "22"`}, + hdr: []interface{}{"list", []string{"1", "2"}}, found: true, }, } @@ -560,7 +565,7 @@ func Test_Filtering(t *testing.T) { testCtx, err = event.NewRequestInfoContext(testCtx, info) require.NoError(err) - require.NoError(event.WriteObservation(testCtx, "not-enabled", event.WithHeader(tt.hdr), event.WithFlush())) + require.NoError(event.WriteObservation(testCtx, "not-enabled", event.WithHeader(tt.hdr...), event.WithFlush())) b, err := ioutil.ReadFile(c.AllEvents.Name()) assert.NoError(err) @@ -755,6 +760,30 @@ func Test_WriteAudit(t *testing.T) { cleanup: func() { event.TestResetSystEventer(t) }, auditSinkFileName: c.AllEvents.Name(), }, + { + name: "use-syseventer-with-cancelled-ctx", + noFlush: true, + ctx: func() context.Context { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + return ctx + }(), + auditOpts: [][]event.Option{ + { + event.WithAuth(testAuth), + event.WithRequest(testReq), + }, + }, + wantAudit: &testAudit{ + Auth: testAuth, + Request: testReq, + }, + setup: func() error { + return event.InitSysEventer(testLogger, testLock, "use-syseventer", event.WithEventerConfig(&c.EventerConfig)) + }, + cleanup: func() { event.TestResetSystEventer(t) }, + auditSinkFileName: c.AllEvents.Name(), + }, { name: "simple", ctx: ctx, @@ -913,6 +942,7 @@ func Test_WriteError(t *testing.T) { name string ctx context.Context e error + opt []event.Option info *event.RequestInfo setup func() error cleanup func() @@ -944,6 +974,20 @@ func Test_WriteError(t *testing.T) { cleanup: func() { event.TestResetSystEventer(t) }, errSinkFileName: c.ErrorEvents.Name(), }, + { + name: "use-syseventer-with-cancelled-ctx", + ctx: func() context.Context { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + return ctx + }(), + e: &testError, + setup: func() error { + return event.InitSysEventer(testLogger, testLock, "use-syseventer", event.WithEventerConfig(&c.EventerConfig)) + }, + cleanup: func() { event.TestResetSystEventer(t) }, + errSinkFileName: c.ErrorEvents.Name(), + }, { name: "no-info-id", ctx: testCtxNoInfoId, @@ -962,6 +1006,22 @@ func Test_WriteError(t *testing.T) { info: info, errSinkFileName: c.ErrorEvents.Name(), }, + { + name: "simple-with-opt", + ctx: testCtx, + e: &testError, + opt: []event.Option{event.WithInfo("test", "info")}, + info: info, + errSinkFileName: c.ErrorEvents.Name(), + }, + { + name: "stderrors", + ctx: testCtx, + e: stderrors.New("test std errors"), + opt: []event.Option{event.WithInfo("test", "info")}, + info: info, + errSinkFileName: c.ErrorEvents.Name(), + }, } for _, tt := range tests { @@ -977,7 +1037,7 @@ func Test_WriteError(t *testing.T) { if tt.noOperation { op = "" } - event.WriteError(tt.ctx, event.Op(op), tt.e) + event.WriteError(tt.ctx, event.Op(op), tt.e, tt.opt...) if tt.errSinkFileName != "" { defer func() { _ = os.WriteFile(tt.errSinkFileName, nil, 0o666) }() b, err := ioutil.ReadFile(tt.errSinkFileName) @@ -991,14 +1051,17 @@ func Test_WriteError(t *testing.T) { gotError := &cloudevents.Event{} err = json.Unmarshal(b, gotError) require.NoErrorf(err, "json: %s", string(b)) + fmt.Println("raw: ", string(b)) require.NoError(err) - actualError := fakeError{ - Msg: gotError.Data.(map[string]interface{})["error"].(map[string]interface{})["Msg"].(string), - Code: gotError.Data.(map[string]interface{})["error"].(map[string]interface{})["Code"].(string), + if _, ok := gotError.Data.(map[string]interface{})["error_fields"].(map[string]interface{})["Msg"]; ok { + actualError := fakeError{ + Msg: gotError.Data.(map[string]interface{})["error_fields"].(map[string]interface{})["Msg"].(string), + Code: gotError.Data.(map[string]interface{})["error_fields"].(map[string]interface{})["Code"].(string), + } + assert.Equal(tt.e, &actualError) } - assert.Equal(tt.e, &actualError) } }) @@ -1029,7 +1092,8 @@ func Test_WriteSysEvent(t *testing.T) { tests := []struct { name string ctx context.Context - data map[string]interface{} + data []interface{} + msg string info *event.RequestInfo setup func() error cleanup func() @@ -1045,20 +1109,38 @@ func Test_WriteSysEvent(t *testing.T) { { name: "missing-caller", ctx: ctx, - data: map[string]interface{}{"data": "test-data"}, + msg: "hello", + data: []interface{}{"data", "test-data"}, noOperation: true, }, { name: "syseventer-not-initialized", ctx: context.Background(), - data: map[string]interface{}{"data": "test-data"}, + msg: "hello", + data: []interface{}{"data", "test-data"}, sinkFileName: c.AllEvents.Name(), noOutput: true, }, { name: "use-syseventer", ctx: context.Background(), - data: map[string]interface{}{"data": "test-data", event.ServerName: "test-server", event.ServerAddress: "localhost"}, + msg: "hello", + data: []interface{}{"data", "test-data", event.ServerName, "test-server", event.ServerAddress, "localhost"}, + setup: func() error { + return event.InitSysEventer(testLogger, testLock, "use-syseventer", event.WithEventerConfig(&c.EventerConfig)) + }, + cleanup: func() { event.TestResetSystEventer(t) }, + sinkFileName: c.AllEvents.Name(), + }, + { + name: "use-syseventer-with-cancelled-ctx", + ctx: func() context.Context { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + return ctx + }(), + msg: "hello", + data: []interface{}{"data", "test-data", event.ServerName, "test-server", event.ServerAddress, "localhost"}, setup: func() error { return event.InitSysEventer(testLogger, testLock, "use-syseventer", event.WithEventerConfig(&c.EventerConfig)) }, @@ -1080,7 +1162,7 @@ func Test_WriteSysEvent(t *testing.T) { if tt.noOperation { op = "" } - event.WriteSysEvent(tt.ctx, event.Op(op), tt.data) + event.WriteSysEvent(tt.ctx, event.Op(op), tt.msg, tt.data...) if tt.sinkFileName != "" { defer func() { _ = os.WriteFile(tt.sinkFileName, nil, 0o666) }() b, err := ioutil.ReadFile(tt.sinkFileName) @@ -1095,8 +1177,66 @@ func Test_WriteSysEvent(t *testing.T) { err = json.Unmarshal(b, gotSysEvent) require.NoErrorf(err, "json: %s", string(b)) - assert.Equal(tt.data, gotSysEvent.Data.(map[string]interface{})["data"].(map[string]interface{})) + expected := event.ConvertArgs(tt.data...) + expected["msg"] = tt.msg + assert.Equal(expected, gotSysEvent.Data.(map[string]interface{})["data"].(map[string]interface{})) } }) } } + +func TestConvertArgs(t *testing.T) { + tests := []struct { + name string + args []interface{} + want map[string]interface{} + }{ + { + name: "no-args", + args: []interface{}{}, + want: nil, + }, + { + name: "nil-first-arg", + args: []interface{}{nil}, + want: map[string]interface{}{ + event.MissingKey: nil, + }, + }, + { + name: "odd-number-of-args", + args: []interface{}{1, 2, 3}, + want: map[string]interface{}{ + "1": 2, + event.MissingKey: 3, + }, + }, + { + name: "struct-key", + args: []interface{}{[]struct{ name string }{{name: "alice"}}, 1}, + want: map[string]interface{}{ + "[{alice}]": 1, + }, + }, + { + name: "test-key-with-stringer", + args: []interface{}{testIntKeyWithStringer(11), "eleven"}, + want: map[string]interface{}{ + "*11*": "eleven", + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert := assert.New(t) + got := event.ConvertArgs(tt.args...) + assert.Equal(tt.want, got) + }) + } +} + +type testIntKeyWithStringer int + +func (ti testIntKeyWithStringer) String() string { + return fmt.Sprint("*", int(ti), "*") +} diff --git a/internal/observability/event/context_unexported_test.go b/internal/observability/event/context_unexported_test.go new file mode 100644 index 000000000..81822c8de --- /dev/null +++ b/internal/observability/event/context_unexported_test.go @@ -0,0 +1,80 @@ +package event + +import ( + "context" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func Test_newSendCtx(t *testing.T) { + testInfo := &RequestInfo{ + EventId: "test-id", + Id: "test-id", + } + tests := []struct { + name string + ctx context.Context + wantCancel bool + wantInfo bool + }{ + { + name: "cancelled-with-info", + ctx: func() context.Context { + var err error + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + ctx, err = NewRequestInfoContext(ctx, testInfo) + require.NoError(t, err) + return ctx + }(), + wantCancel: true, + wantInfo: true, + }, + { + name: "cancelled-no-info", + ctx: func() context.Context { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + return ctx + }(), + wantCancel: true, + }, + { + name: "no-info", + ctx: context.Background(), + wantInfo: false, + }, + { + name: "with-info", + ctx: func() context.Context { + ctx, err := NewRequestInfoContext(context.Background(), testInfo) + require.NoError(t, err) + return ctx + }(), + wantInfo: true, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + ctx, cancel := newSendCtx(tt.ctx) + require.NotNil(ctx) + assert.True(ctx.Err() != context.Canceled) + if tt.wantCancel { + require.NotNil(cancel) + } else { + require.Nil(cancel) + } + info, ok := RequestInfoFromContext(ctx) + if tt.wantInfo { + assert.True(ok) + assert.NotNil(info) + } else { + assert.False(ok) + assert.Nil(info) + } + }) + } +} diff --git a/internal/observability/event/event_error.go b/internal/observability/event/event_error.go index ca537c498..5ee479b1b 100644 --- a/internal/observability/event/event_error.go +++ b/internal/observability/event/event_error.go @@ -8,11 +8,13 @@ import ( const errorVersion = "v0.1" type err struct { - Error error `json:"error"` - Id Id `json:"id,omitempty"` - Version string `json:"version"` - Op Op `json:"op,omitempty"` - RequestInfo *RequestInfo `json:"request_info,omitempty"` + Error string `json:"error"` + ErrorFields error `json:"error_fields"` + Id Id `json:"id,omitempty"` + Version string `json:"version"` + Op Op `json:"op,omitempty"` + RequestInfo *RequestInfo `json:"request_info,omitempty"` + Info map[string]interface{} `json:"info,omitempty"` } func newError(fromOperation Op, e error, opt ...Option) (*err, error) { @@ -36,7 +38,9 @@ func newError(fromOperation Op, e error, opt ...Option) (*err, error) { Op: fromOperation, Version: errorVersion, RequestInfo: opts.withRequestInfo, - Error: e, + Info: opts.withInfo, + Error: e.Error(), + ErrorFields: e, } if err := newErr.validate(); err != nil { return nil, fmt.Errorf("%s: %w", op, err) @@ -55,7 +59,10 @@ func (e *err) validate() error { if e.Op == "" { return fmt.Errorf("%s: missing operation: %w", op, ErrInvalidParameter) } - if e.Error == nil { + if e.ErrorFields == nil { + return fmt.Errorf("%s: missing error fields: %w", op, ErrInvalidParameter) + } + if e.Error == "" { return fmt.Errorf("%s: missing error: %w", op, ErrInvalidParameter) } return nil diff --git a/internal/observability/event/event_error_test.go b/internal/observability/event/event_error_test.go index d8d9ee8c4..e6c0f5d0f 100644 --- a/internal/observability/event/event_error_test.go +++ b/internal/observability/event/event_error_test.go @@ -37,9 +37,10 @@ func Test_newError(t *testing.T) { fromOp: Op("valid-no-opts"), e: fmt.Errorf("%s: valid no opts: %w", "valid-no-opts", ErrInvalidParameter), want: &err{ - Error: fmt.Errorf("%s: valid no opts: %w", "valid-no-opts", ErrInvalidParameter), - Version: errorVersion, - Op: Op("valid-no-opts"), + ErrorFields: fmt.Errorf("%s: valid no opts: %w", "valid-no-opts", ErrInvalidParameter), + Error: "valid-no-opts: valid no opts: invalid parameter", + Version: errorVersion, + Op: Op("valid-no-opts"), }, }, { @@ -49,13 +50,16 @@ func Test_newError(t *testing.T) { opts: []Option{ WithId("valid-all-opts"), WithRequestInfo(TestRequestInfo(t)), + WithInfo("msg", "hello"), }, want: &err{ - Error: fmt.Errorf("%s: valid all opts: %w", "valid-all-opts", ErrInvalidParameter), + ErrorFields: fmt.Errorf("%s: valid all opts: %w", "valid-all-opts", ErrInvalidParameter), + Error: "valid-all-opts: valid all opts: invalid parameter", Version: errorVersion, Op: Op("valid-all-opts"), Id: "valid-all-opts", RequestInfo: TestRequestInfo(t), + Info: map[string]interface{}{"msg": "hello"}, }, }, } @@ -92,38 +96,57 @@ func Test_errvalidate(t *testing.T) { name string id string op Op - want error + wantError string + wantFields error wantErrIs error wantErrContains string }{ { name: "missing-id", op: Op("missing-id"), - want: fmt.Errorf("%s: missing id: %w", "missing-id", ErrInvalidParameter), + wantFields: fmt.Errorf("%s: missing id: %w", "missing-id", ErrInvalidParameter), wantErrIs: ErrInvalidParameter, wantErrContains: "missing id", }, { name: "missing-operation", id: "missing-operation", - want: fmt.Errorf("%s: missing operation: %w", "missing-operation", ErrInvalidParameter), + wantFields: fmt.Errorf("%s: missing operation: %w", "missing-operation", ErrInvalidParameter), wantErrIs: ErrInvalidParameter, wantErrContains: "missing operation", }, { - name: "valid", - op: Op("valid"), - id: "valid", - want: fmt.Errorf("%s: valid error: %w", "valid-error", ErrInvalidParameter), + name: "missing-error", + op: Op("missing-error"), + id: "missing-error", + wantFields: fmt.Errorf("%s: missing operation: %w", "missing-operation", ErrInvalidParameter), + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing error", + }, + { + name: "missing-error-fields", + op: Op("missing-error-fields"), + id: "missing-error-fields", + wantError: "test error", + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing error", + }, + { + name: "valid", + op: Op("valid"), + id: "valid", + wantFields: fmt.Errorf("%s: valid error: %w", "valid-error", ErrInvalidParameter), + wantError: "test error", }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { assert, require := assert.New(t), require.New(t) e := err{ - Op: tt.op, - Id: Id(tt.id), - Error: tt.want, + Op: tt.op, + Id: Id(tt.id), + ErrorFields: tt.wantFields, + Error: tt.wantError, } err := e.validate() if tt.wantErrIs != nil { @@ -135,7 +158,8 @@ func Test_errvalidate(t *testing.T) { return } assert.NoError(err) - assert.Equal(tt.want, e.Error) + assert.Equal(tt.wantFields, e.ErrorFields) + assert.Equal(tt.wantError, e.Error) }) } } diff --git a/internal/observability/event/event_observation_test.go b/internal/observability/event/event_observation_test.go index 8744670b9..73fa81daa 100644 --- a/internal/observability/event/event_observation_test.go +++ b/internal/observability/event/event_observation_test.go @@ -13,14 +13,9 @@ func Test_newObservation(t *testing.T) { now := time.Now() - testHeader := map[string]interface{}{ - "public-id": "public-id", - "now": now, - } + testHeader := []interface{}{"public-id", "public-id", "now", now} - testDetails := map[string]interface{}{ - "file_name": "tmpfile-name", - } + testDetails := []interface{}{"file_name", "tmpfile-name"} tests := []struct { name string @@ -49,14 +44,14 @@ func Test_newObservation(t *testing.T) { opts: []Option{ WithId("valid-all-opts"), WithRequestInfo(TestRequestInfo(t)), - WithHeader(testHeader), - WithDetails(testDetails), + WithHeader(testHeader...), + WithDetails(testDetails...), WithFlush(), }, want: &observation{ ID: "valid-all-opts", - Header: testHeader, - Detail: testDetails, + Header: map[string]interface{}{"public-id": "public-id", "now": now}, + Detail: map[string]interface{}{"file_name": "tmpfile-name"}, Flush: true, Version: errorVersion, Op: Op("valid-all-opts"), diff --git a/internal/observability/event/event_sys.go b/internal/observability/event/event_sys.go index 3304fa358..cfc4d217d 100644 --- a/internal/observability/event/event_sys.go +++ b/internal/observability/event/event_sys.go @@ -4,7 +4,7 @@ package event const sysVersion = "v0.1" type sysEvent struct { - Id Id `json:"id,omitempty"` + Id Id `json:"-"` Version string `json:"version"` Op Op `json:"op,omitempty"` Data map[string]interface{} `json:"data"` diff --git a/internal/observability/event/id.go b/internal/observability/event/id.go index 239f13d31..2539c3f60 100644 --- a/internal/observability/event/id.go +++ b/internal/observability/event/id.go @@ -6,7 +6,7 @@ import ( "github.com/hashicorp/go-secure-stdlib/base62" ) -const idPrefix = "e" +const IdPrefix = "e" // NewId is a bit of a modified NewId has been done to stop a circular // dependency with the errors package that is caused by importing diff --git a/internal/observability/event/options.go b/internal/observability/event/options.go index fddcbceab..34e39f1db 100644 --- a/internal/observability/event/options.go +++ b/internal/observability/event/options.go @@ -5,6 +5,8 @@ import ( "time" ) +const msgField = "msg" + // getOpts - iterate the inbound Options and return a struct. func getOpts(opt ...Option) options { opts := getDefaultOptions() @@ -25,6 +27,7 @@ type options struct { withDetails map[string]interface{} withHeader map[string]interface{} withFlush bool + withInfo map[string]interface{} withRequestInfo *RequestInfo withNow time.Time withRequest *Request @@ -53,17 +56,19 @@ func WithId(id string) Option { } } -// WithDetails allows an optional map as details -func WithDetails(d map[string]interface{}) Option { +// WithDetails allows an optional set of key/value pairs about an observation +// event at the detail level and observation events may have multiple "details" +func WithDetails(args ...interface{}) Option { return func(o *options) { - o.withDetails = d + o.withDetails = ConvertArgs(args...) } } -// WithHeader allows an optional map as a header -func WithHeader(d map[string]interface{}) Option { +// WithHeader allows an optional set of key/value pairs about an event at the +// header level and observation events will only have one "header" +func WithHeader(args ...interface{}) Option { return func(o *options) { - o.withHeader = d + o.withHeader = ConvertArgs(args...) } } @@ -74,6 +79,35 @@ func WithFlush() Option { } } +// WithInfo allows an optional info key/value pairs about an error event. If +// used in conjunction with the WithInfoMsg(...) option, and WithInfoMsg(...) is +// specified after WithInfo(...), then WithInfoMsg(...) will overwrite any +// values from WithInfo(...). It's recommend that these two options not be used +// together. +func WithInfo(args ...interface{}) Option { + return func(o *options) { + o.withInfo = ConvertArgs(args...) + } +} + +// WithInfoMsg allows an optional msg and optional info key/value pairs about an +// error event. If used in conjunction with the WithInfo(...) option, and +// WithInfo(...) is specified after WithInfoMsg(...), then WithInfo(...) will +// overwrite any values from WithInfo(...). It's recommend that these two +// options not be used together. +func WithInfoMsg(msg string, args ...interface{}) Option { + return func(o *options) { + o.withInfo = ConvertArgs(args...) + if o.withInfo == nil { + o.withInfo = map[string]interface{}{ + msgField: msg, + } + return + } + o.withInfo[msgField] = msg + } +} + // WithRequestInfo allows an optional RequestInfo func WithRequestInfo(i *RequestInfo) Option { return func(o *options) { diff --git a/internal/observability/event/options_test.go b/internal/observability/event/options_test.go index 9549b6a4f..c8a89bd0a 100644 --- a/internal/observability/event/options_test.go +++ b/internal/observability/event/options_test.go @@ -21,22 +21,20 @@ func Test_GetOpts(t *testing.T) { }) t.Run("WithDetails", func(t *testing.T) { assert := assert.New(t) - d := map[string]interface{}{ + opts := getOpts(WithDetails("name", "alice")) + testOpts := getDefaultOptions() + testOpts.withDetails = map[string]interface{}{ "name": "alice", } - opts := getOpts(WithDetails(d)) - testOpts := getDefaultOptions() - testOpts.withDetails = d assert.Equal(opts, testOpts) }) t.Run("WithHeader", func(t *testing.T) { assert := assert.New(t) - h := map[string]interface{}{ + opts := getOpts(WithHeader("name", "alice")) + testOpts := getDefaultOptions() + testOpts.withHeader = map[string]interface{}{ "name": "alice", } - opts := getOpts(WithHeader(h)) - testOpts := getDefaultOptions() - testOpts.withHeader = h assert.Equal(opts, testOpts) }) t.Run("WithFlush", func(t *testing.T) { @@ -46,6 +44,31 @@ func Test_GetOpts(t *testing.T) { testOpts.withFlush = true assert.Equal(opts, testOpts) }) + t.Run("WithInfo", func(t *testing.T) { + assert := assert.New(t) + opts := getOpts(WithInfo("name", "alice")) + testOpts := getDefaultOptions() + testOpts.withInfo = map[string]interface{}{"name": "alice"} + assert.Equal(opts, testOpts) + + opts = getOpts(WithInfoMsg("test"), WithInfo("name", "alice")) + testOpts.withInfo = map[string]interface{}{"name": "alice"} + assert.Equal(opts, testOpts) + }) + t.Run("WithInfoMsg", func(t *testing.T) { + assert := assert.New(t) + opts := getOpts(WithInfoMsg("test", "name", "alice")) + testOpts := getDefaultOptions() + testOpts.withInfo = map[string]interface{}{msgField: "test", "name": "alice"} + assert.Equal(opts, testOpts) + + opts = getOpts(WithInfo("name", "alice"), WithInfoMsg("test", "name", "eve")) + testOpts.withInfo = map[string]interface{}{ + "msg": "test", + "name": "eve", + } + assert.Equal(opts, testOpts) + }) t.Run("WithRequestInfo", func(t *testing.T) { assert := assert.New(t) info := TestRequestInfo(t) diff --git a/internal/perms/acl.go b/internal/perms/acl.go index 98243f34e..2b92f141c 100644 --- a/internal/perms/acl.go +++ b/internal/perms/acl.go @@ -44,17 +44,17 @@ type ACLResults struct { // capabilities. Resources must have a ScopeId. type Resource struct { // ScopeId is the scope that contains the Resource. - ScopeId string + ScopeId string `json:"scope_id,omitempty"` // Id is the public id of the resource. - Id string + Id string `json:"id,omitempty"` // Type of resource. - Type resource.Type + Type resource.Type `json:"type,omitempty"` // Pin if defined would constrain the resource within the collection of the // pin id. - Pin string + Pin string `json:"pin,omitempty"` } // NewACL creates an ACL from the grants provided. diff --git a/internal/perms/acl_test.go b/internal/perms/acl_test.go index 20699e412..c14edd65a 100644 --- a/internal/perms/acl_test.go +++ b/internal/perms/acl_test.go @@ -1,6 +1,7 @@ package perms import ( + "encoding/json" "fmt" "testing" @@ -335,3 +336,16 @@ func Test_ACLAllowed(t *testing.T) { }) } } + +func TestJsonMarshal(t *testing.T) { + res := &Resource{ + ScopeId: "scope", + Id: "id", + Type: resource.Controller, + Pin: "", + } + + out, err := json.Marshal(res) + require.NoError(t, err) + assert.Equal(t, `{"scope_id":"scope","id":"id","type":"controller"}`, string(out)) +} diff --git a/internal/scheduler/additional_verification_test.go b/internal/scheduler/additional_verification_test.go index d89b8f674..67b4d0561 100644 --- a/internal/scheduler/additional_verification_test.go +++ b/internal/scheduler/additional_verification_test.go @@ -5,24 +5,34 @@ import ( "errors" "fmt" "runtime" + "sync" "testing" "time" "github.com/hashicorp/boundary/internal/db" "github.com/hashicorp/boundary/internal/iam" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/scheduler/job" + "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func TestSchedulerWorkflow(t *testing.T) { - t.Parallel() + // do not use t.Parallel() since it relies on the sys eventer assert, require := assert.New(t), require.New(t) conn, _ := db.TestSetup(t, "postgres") wrapper := db.TestWrapper(t) iam.TestRepo(t, conn, wrapper) - + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerWorkflow", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithRunJobsInterval(time.Second)) job1Ch := make(chan error) @@ -32,7 +42,7 @@ func TestSchedulerWorkflow(t *testing.T) { return <-job1Ch } tj1 := testJob{name: "name1", description: "desc", fn: fn1, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj1) + err = sched.RegisterJob(context.Background(), tj1) require.NoError(err) job2Ch := make(chan error) @@ -44,8 +54,10 @@ func TestSchedulerWorkflow(t *testing.T) { tj2 := testJob{name: "name2", description: "desc", fn: fn2, nextRunIn: time.Hour} err = sched.RegisterJob(context.Background(), tj2) require.NoError(err) - - err = sched.Start(context.Background()) + baseCtx, baseCnl := context.WithCancel(context.Background()) + defer baseCnl() + var wg sync.WaitGroup + err = sched.Start(baseCtx, &wg) require.NoError(err) // Wait for scheduler to run both jobs @@ -78,21 +90,31 @@ func TestSchedulerWorkflow(t *testing.T) { } func TestSchedulerCancelCtx(t *testing.T) { - t.Parallel() + // do not use t.Parallel() since it relies on the sys eventer assert, require := assert.New(t), require.New(t) conn, _ := db.TestSetup(t, "postgres") wrapper := db.TestWrapper(t) iam.TestRepo(t, conn, wrapper) + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerCancelCtx", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithRunJobsInterval(time.Second)) fn, jobReady, jobDone := testJobFn() tj := testJob{name: "name", description: "desc", fn: fn, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj) + err = sched.RegisterJob(context.Background(), tj) require.NoError(err) baseCtx, baseCnl := context.WithCancel(context.Background()) - err = sched.Start(baseCtx) + var wg sync.WaitGroup + defer wg.Wait() + err = sched.Start(baseCtx, &wg) require.NoError(err) // Wait for scheduler to run job @@ -116,19 +138,27 @@ func TestSchedulerCancelCtx(t *testing.T) { } func TestSchedulerInterruptedCancelCtx(t *testing.T) { - t.Parallel() + // do not use t.Parallel() since it relies on the sys eventer assert, require := assert.New(t), require.New(t) conn, _ := db.TestSetup(t, "postgres") wrapper := db.TestWrapper(t) rw := db.New(conn) kmsCache := kms.TestKms(t, conn, wrapper) iam.TestRepo(t, conn, wrapper) + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerInterruptedCancelCtx", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithRunJobsInterval(time.Second), WithMonitorInterval(time.Second)) fn, job1Ready, job1Done := testJobFn() tj1 := testJob{name: "name1", description: "desc", fn: fn, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj1) + err = sched.RegisterJob(context.Background(), tj1) require.NoError(err) fn, job2Ready, job2Done := testJobFn() @@ -138,7 +168,9 @@ func TestSchedulerInterruptedCancelCtx(t *testing.T) { baseCtx, baseCnl := context.WithCancel(context.Background()) defer baseCnl() - err = sched.Start(baseCtx) + var wg sync.WaitGroup + wg.Wait() + err = sched.Start(baseCtx, &wg) require.NoError(err) // Wait for scheduler to run both job @@ -208,13 +240,21 @@ func TestSchedulerInterruptedCancelCtx(t *testing.T) { } func TestSchedulerJobProgress(t *testing.T) { - t.Parallel() + // do not use t.Parallel() since it relies on the sys eventer assert, require := assert.New(t), require.New(t) conn, _ := db.TestSetup(t, "postgres") wrapper := db.TestWrapper(t) rw := db.New(conn) kmsCache := kms.TestKms(t, conn, wrapper) iam.TestRepo(t, conn, wrapper) + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerWorkflow", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithRunJobsInterval(time.Second), WithMonitorInterval(time.Second)) @@ -232,11 +272,13 @@ func TestSchedulerJobProgress(t *testing.T) { return <-jobStatus } tj := testJob{name: "name", description: "desc", fn: fn, statusFn: status, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj) + err = sched.RegisterJob(context.Background(), tj) require.NoError(err) baseCtx, baseCnl := context.WithCancel(context.Background()) - err = sched.Start(baseCtx) + var wg sync.WaitGroup + defer wg.Wait() + err = sched.Start(baseCtx, &wg) require.NoError(err) // Wait for scheduler to run job @@ -295,13 +337,21 @@ func TestSchedulerJobProgress(t *testing.T) { } func TestSchedulerMonitorLoop(t *testing.T) { - t.Parallel() + // do not use t.Parallel() since it relies on the sys eventer assert, require := assert.New(t), require.New(t) conn, _ := db.TestSetup(t, "postgres") wrapper := db.TestWrapper(t) rw := db.New(conn) kmsCache := kms.TestKms(t, conn, wrapper) iam.TestRepo(t, conn, wrapper) + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerWorkflow", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithInterruptThreshold(time.Second), WithRunJobsInterval(time.Second), WithMonitorInterval(time.Second)) @@ -314,12 +364,14 @@ func TestSchedulerMonitorLoop(t *testing.T) { return nil } tj := testJob{name: "name", description: "desc", fn: fn, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj) + err = sched.RegisterJob(context.Background(), tj) require.NoError(err) baseCtx, baseCnl := context.WithCancel(context.Background()) - defer baseCnl() - err = sched.Start(baseCtx) + + var wg sync.WaitGroup + defer wg.Wait() + err = sched.Start(baseCtx, &wg) require.NoError(err) // Wait for scheduler to run job @@ -338,6 +390,7 @@ func TestSchedulerMonitorLoop(t *testing.T) { run, err := repo.LookupRun(context.Background(), runId) require.NoError(err) assert.Equal(string(job.Interrupted), run.Status) + baseCnl() } func TestSchedulerFinalStatusUpdate(t *testing.T) { @@ -348,6 +401,14 @@ func TestSchedulerFinalStatusUpdate(t *testing.T) { rw := db.New(conn) kmsCache := kms.TestKms(t, conn, wrapper) iam.TestRepo(t, conn, wrapper) + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestSchedulerFinalStatusUpdate", event.WithEventerConfig(testConfig)) + require.NoError(err) sched := TestScheduler(t, conn, wrapper, WithRunJobsLimit(10), WithRunJobsInterval(time.Second)) @@ -363,7 +424,7 @@ func TestSchedulerFinalStatusUpdate(t *testing.T) { return <-jobStatus } tj := testJob{name: "name", description: "desc", fn: fn, statusFn: status, nextRunIn: time.Hour} - err := sched.RegisterJob(context.Background(), tj) + err = sched.RegisterJob(context.Background(), tj) require.NoError(err) baseCtx, baseCnl := context.WithCancel(context.Background()) diff --git a/internal/scheduler/scheduler.go b/internal/scheduler/scheduler.go index 9d5f87f02..66d58dfcc 100644 --- a/internal/scheduler/scheduler.go +++ b/internal/scheduler/scheduler.go @@ -7,6 +7,7 @@ import ( "time" "github.com/hashicorp/boundary/internal/errors" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/scheduler/job" "github.com/hashicorp/go-hclog" ua "go.uber.org/atomic" @@ -131,10 +132,10 @@ func (s *Scheduler) UpdateJobNextRunInAtLeast(ctx context.Context, name string, // new jobs once the ctx past in is canceled. // The scheduler cannot be started again once the ctx is canceled, a new scheduler will // need to be instantiated in order to begin scheduling again. -func (s *Scheduler) Start(ctx context.Context) error { +func (s *Scheduler) Start(ctx context.Context, wg *sync.WaitGroup) error { const op = "scheduler.(Scheduler).Start" if !s.started.CAS(s.started.Load(), true) { - s.logger.Debug("scheduler already started, skipping") + event.WriteSysEvent(ctx, op, "scheduler already started, skipping") return nil } @@ -153,57 +154,64 @@ func (s *Scheduler) Start(ctx context.Context) error { return errors.Wrap(err, op) } - go s.start(ctx) - go s.monitorJobs(ctx) + if wg != nil { + wg.Add(2) + } + go func() { + defer wg.Done() + s.start(ctx) + }() + go func() { + defer wg.Done() + s.monitorJobs(ctx) + }() return nil } func (s *Scheduler) start(ctx context.Context) { - s.logger.Debug("starting scheduling loop", "server id", s.serverId) + const op = "scheduler.(Scheduler).start" timer := time.NewTimer(s.runJobsInterval) for { select { case <-ctx.Done(): - s.logger.Debug("scheduling loop shutting down", "server id", s.serverId) + event.WriteSysEvent(ctx, op, "scheduling loop shutting down", "server id", s.serverId) return case <-timer.C: - s.logger.Debug("waking up to run jobs", "server id", s.serverId) repo, err := s.jobRepoFn() if err != nil { - s.logger.Error("error creating job repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error creating job repo")) break } runs, err := repo.RunJobs(ctx, s.serverId, job.WithRunJobsLimit(s.runJobsLimit)) if err != nil { - s.logger.Error("error getting jobs to run from repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error getting jobs to run from repo")) break } for _, r := range runs { err := s.runJob(ctx, r) if err != nil { - s.logger.Error("error starting job", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error starting job")) if _, inner := repo.FailRun(ctx, r.PrivateId, 0, 0); inner != nil { - s.logger.Error("error updating failed job run", "error", inner) + event.WriteError(ctx, op, inner, event.WithInfoMsg("error updating failed job run")) } } } } - s.logger.Debug("scheduling loop going back to sleep", "server id", s.serverId) timer.Reset(s.runJobsInterval) } } func (s *Scheduler) runJob(ctx context.Context, r *job.Run) error { + const op = "scheduler.(Scheduler).runJob" regJob, ok := s.registeredJobs.Load(r.JobName) if !ok { return fmt.Errorf("job %q not registered on scheduler", r.JobName) } - s.logger.Debug("starting job run", "run id", r.PrivateId, "job name", r.JobName) repo, err := s.jobRepoFn() if err != nil { @@ -229,19 +237,18 @@ func (s *Scheduler) runJob(ctx context.Context, r *job.Run) error { switch runErr { case nil: - s.logger.Debug("job run complete", "run id", r.PrivateId, "name", j.Name()) nextRun, inner := j.NextRunIn() if inner != nil { - s.logger.Error("error getting next run time", "name", j.Name(), "error", inner) + event.WriteError(ctx, op, inner, event.WithInfoMsg("error getting next run time", "name", j.Name())) } _, updateErr = repo.CompleteRun(jobContext, r.PrivateId, nextRun, status.Completed, status.Total) default: - s.logger.Debug("job run failed", "run id", r.PrivateId, "name", j.Name(), "error", runErr) + event.WriteError(ctx, op, runErr, event.WithInfoMsg("job run failed", "run id", r.PrivateId, "name", j.Name())) _, updateErr = repo.FailRun(jobContext, r.PrivateId, status.Completed, status.Total) } if updateErr != nil { - s.logger.Error("error updating job run", "name", j.Name(), "error", updateErr) + event.WriteError(ctx, op, updateErr, event.WithInfoMsg("error updating job run", "name", j.Name())) } s.runningJobs.Delete(j.Name()) }() @@ -250,12 +257,12 @@ func (s *Scheduler) runJob(ctx context.Context, r *job.Run) error { } func (s *Scheduler) monitorJobs(ctx context.Context) { - s.logger.Debug("starting job monitor loop") + const op = "scheduler.(Scheduler).monitorJobs" timer := time.NewTimer(0) for { select { case <-ctx.Done(): - s.logger.Debug("job monitor loop shutting down") + event.WriteSysEvent(ctx, op, "job monitor loop shutting down") return case <-timer.C: @@ -263,7 +270,7 @@ func (s *Scheduler) monitorJobs(ctx context.Context) { s.runningJobs.Range(func(_, v interface{}) bool { err := s.updateRunningJobProgress(ctx, v.(*runningJob)) if err != nil { - s.logger.Error("error updating job progress", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error updating job progress")) } return true }) @@ -271,13 +278,13 @@ func (s *Scheduler) monitorJobs(ctx context.Context) { // Check for defunct runs to interrupt repo, err := s.jobRepoFn() if err != nil { - s.logger.Error("error creating job repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error creating job repo")) break } _, err = repo.InterruptRuns(ctx, s.interruptThreshold) if err != nil { - s.logger.Error("error interrupting job runs", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error interrupting job runs")) } } timer.Reset(s.monitorInterval) diff --git a/internal/servers/common/handler.go b/internal/servers/common/handler.go index eba78dd91..463e7946a 100644 --- a/internal/servers/common/handler.go +++ b/internal/servers/common/handler.go @@ -10,13 +10,12 @@ import ( "github.com/hashicorp/boundary/internal/kms" "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers/controller/auth" - "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/base62" ) -// generatedTraceId returns a boundary generated TraceId or "" if an error occurs when generating +// GeneratedTraceId returns a boundary generated TraceId or "" if an error occurs when generating // the id. -func generatedTraceId(ctx context.Context) string { +func GeneratedTraceId(ctx context.Context) string { t, err := base62.Random(20) if err != nil { return "" @@ -103,7 +102,7 @@ func WrapWithOptionals(with *writerWrapper, wrap http.ResponseWriter) (http.Resp // WrapWithEventsHandler will wrap the provided http.Handler with a // handler that adds an Eventer to the request context and starts/flushes gated // events of type: observation and audit -func WrapWithEventsHandler(h http.Handler, e *event.Eventer, logger hclog.Logger, kms *kms.Kms) (http.Handler, error) { +func WrapWithEventsHandler(h http.Handler, e *event.Eventer, kms *kms.Kms) (http.Handler, error) { const op = "common.WrapWithEventsHandler" if h == nil { return nil, errors.New(errors.InvalidParameter, op, "missing handler") @@ -111,26 +110,23 @@ func WrapWithEventsHandler(h http.Handler, e *event.Eventer, logger hclog.Logger if e == nil { return nil, errors.New(errors.InvalidParameter, op, "missing eventer") } - if logger == nil { - return nil, errors.New(errors.InvalidParameter, op, "missing logger") - } if kms == nil { return nil, errors.New(errors.InvalidParameter, op, "missing kms") } return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { ctx := r.Context() - publicId, _, _ := auth.GetTokenFromRequest(logger, kms, r) + publicId, _, _ := auth.GetTokenFromRequest(ctx, kms, r) var err error - id, err := event.NewId("e") + id, err := event.NewId(event.IdPrefix) if err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to create id for event", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to create id for event", "method", r.Method, "url", r.URL.RequestURI())) return } info := &event.RequestInfo{ EventId: id, - Id: generatedTraceId(ctx), + Id: GeneratedTraceId(ctx), PublicId: publicId, Method: r.Method, Path: r.URL.RequestURI(), @@ -138,13 +134,13 @@ func WrapWithEventsHandler(h http.Handler, e *event.Eventer, logger hclog.Logger ctx, err = event.NewRequestInfoContext(ctx, info) if err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to create context with request info", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(r.Context(), op, err, event.WithInfoMsg("unable to create context with request info", "method", r.Method, "url", r.URL.RequestURI())) return } ctx, err = event.NewEventerContext(ctx, e) if err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to create context with eventer", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(r.Context(), op, err, event.WithInfoMsg("unable to create context with eventer", "method", r.Method, "url", r.URL.RequestURI())) return } @@ -157,14 +153,14 @@ func WrapWithEventsHandler(h http.Handler, e *event.Eventer, logger hclog.Logger start := time.Now() if err := startGatedEvents(ctx, method, url, start); err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to start gated events", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to start gated events")) return } wrapper, err := WrapWithOptionals(&writerWrapper{w, http.StatusOK}, w) if err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to wrap handler with optional interfaces", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to wrap handler with optional interfaces")) return } h.ServeHTTP(wrapper, r) @@ -172,7 +168,7 @@ func WrapWithEventsHandler(h http.Handler, e *event.Eventer, logger hclog.Logger i, _ := wrapper.(interface{ StatusCode() int }) if err := flushGatedEvents(ctx, method, url, i.StatusCode(), start); err != nil { w.WriteHeader(http.StatusInternalServerError) - logger.Trace("unable to flush gated events", "method", r.Method, "url", r.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to flush gated events")) return } } @@ -187,9 +183,7 @@ func startGatedEvents(ctx context.Context, method, url string, startTime time.Ti if startTime.IsZero() { startTime = time.Now() } - err := event.WriteObservation(ctx, "handler", event.WithHeader(map[string]interface{}{ - "start": startTime, - })) + err := event.WriteObservation(ctx, "handler", event.WithHeader("start", startTime)) if err != nil { return errors.Wrap(err, op, errors.WithMsg("unable to write observation event")) } @@ -211,11 +205,13 @@ func flushGatedEvents(ctx context.Context, method, url string, statusCode int, s if !startTime.IsZero() { latency = float64(stopTime.Sub(startTime)) / float64(time.Millisecond) } - err := event.WriteObservation(ctx, "handler", event.WithFlush(), event.WithHeader(map[string]interface{}{ - "stop": stopTime, - "latency-ms": latency, - "status": statusCode, - })) + err := event.WriteObservation(ctx, "handler", event.WithFlush(), + event.WithHeader( + "stop", stopTime, + "latency-ms", latency, + "status", statusCode, + ), + ) if err != nil { return errors.Wrap(err, op, errors.WithMsg("unable to write and flush observation event")) } diff --git a/internal/servers/common/handler_test.go b/internal/servers/common/handler_test.go index 10c7794c7..8e75636e1 100644 --- a/internal/servers/common/handler_test.go +++ b/internal/servers/common/handler_test.go @@ -188,7 +188,6 @@ func Test_WrapWithEventsHandler(t *testing.T) { name string h http.Handler e *event.Eventer - logger hclog.Logger kms *kms.Kms statusCode int noEventJson bool @@ -198,7 +197,6 @@ func Test_WrapWithEventsHandler(t *testing.T) { { name: "missing handler", e: testEventer, - logger: hclog.Default(), kms: testKms, wantErrMatch: errors.T(errors.InvalidParameter), wantErrContains: "missing handler", @@ -208,24 +206,14 @@ func Test_WrapWithEventsHandler(t *testing.T) { h: http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { fmt.Fprintln(w, "Hello, client") }), - logger: hclog.Default(), kms: testKms, wantErrMatch: errors.T(errors.InvalidParameter), wantErrContains: "missing eventer", }, - { - name: "missing logger", - h: testHander, - e: testEventer, - kms: testKms, - wantErrMatch: errors.T(errors.InvalidParameter), - wantErrContains: "missing logger", - }, { name: "missing kms", h: testHander, e: testEventer, - logger: hclog.Default(), wantErrMatch: errors.T(errors.InvalidParameter), wantErrContains: "missing kms", }, @@ -239,7 +227,6 @@ func Test_WrapWithEventsHandler(t *testing.T) { require.NoError(t, err) return e }(), - logger: hclog.Default(), kms: testKms, statusCode: http.StatusInternalServerError, noEventJson: true, @@ -254,7 +241,6 @@ func Test_WrapWithEventsHandler(t *testing.T) { require.NoError(t, err) return e }(), - logger: hclog.Default(), kms: testKms, statusCode: http.StatusTeapot, // this isn't ideal, but the write by the test handler will send an teapot status noEventJson: true, @@ -263,7 +249,6 @@ func Test_WrapWithEventsHandler(t *testing.T) { name: "success", h: testHander, e: testEventer, - logger: hclog.Default(), kms: testKms, statusCode: http.StatusTeapot, }, @@ -271,7 +256,7 @@ func Test_WrapWithEventsHandler(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { assert, require := assert.New(t), require.New(t) - got, err := WrapWithEventsHandler(tt.h, tt.e, tt.logger, tt.kms) + got, err := WrapWithEventsHandler(tt.h, tt.e, tt.kms) if tt.wantErrMatch != nil { require.Error(err) assert.Nil(got) @@ -484,8 +469,9 @@ type testMockBroker struct { func (b *testMockBroker) Send(ctx context.Context, t eventlogger.EventType, payload interface{}) (eventlogger.Status, error) { const op = "common.(testMockBroker).Send" + _, isGateable := payload.(gated.Gateable) switch { - case b.errorOnFlush && payload.(gated.Gateable).FlushEvent(): + case b.errorOnFlush && isGateable && payload.(gated.Gateable).FlushEvent(): return eventlogger.Status{}, errors.New(errors.Internal, op, "unable to flush event") case b.errorOnSendAudit && t == eventlogger.EventType(event.AuditType): return eventlogger.Status{}, errors.New(errors.Internal, op, "unable to send audit event") diff --git a/internal/servers/controller/auth/auth.go b/internal/servers/controller/auth/auth.go index e6d6dbc84..baf5df273 100644 --- a/internal/servers/controller/auth/auth.go +++ b/internal/servers/controller/auth/auth.go @@ -2,6 +2,7 @@ package auth import ( "context" + stderrors "errors" "fmt" "net/http" "strings" @@ -12,6 +13,7 @@ import ( "github.com/hashicorp/boundary/internal/gen/controller/api/resources/scopes" "github.com/hashicorp/boundary/internal/gen/controller/tokens" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/perms" "github.com/hashicorp/boundary/internal/requests" "github.com/hashicorp/boundary/internal/servers/controller/common" @@ -22,7 +24,6 @@ import ( "github.com/hashicorp/boundary/sdk/recovery" "github.com/hashicorp/go-hclog" wrapping "github.com/hashicorp/go-kms-wrapping" - "github.com/kr/pretty" "github.com/mr-tron/base58" "google.golang.org/protobuf/proto" ) @@ -143,6 +144,7 @@ func NewVerifierContext(ctx context.Context, // proceed, e.g. whether the authn/authz check resulted in failure. If an error // occurs it's logged to the system log. func Verify(ctx context.Context, opt ...Option) (ret VerifyResults) { + const op = "auth.Verify" ret.Error = handlers.ForbiddenError() v, ok := ctx.Value(verifierKey).(*verifier) if !ok { @@ -237,14 +239,14 @@ func Verify(ctx context.Context, opt ...Option) (ret VerifyResults) { } if v.requestInfo.EncryptedToken != "" { - v.decryptToken() + v.decryptToken(ctx) } var authResults perms.ACLResults var err error - authResults, ret.UserId, ret.Scope, v.acl, err = v.performAuthCheck() + authResults, ret.UserId, ret.Scope, v.acl, err = v.performAuthCheck(ctx) if err != nil { - v.logger.Error("error performing authn/authz check", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error performing authn/authz check")) return } @@ -254,7 +256,22 @@ func Verify(ctx context.Context, opt ...Option) (ret VerifyResults) { if v.requestInfo.DisableAuthzFailures { ret.Error = nil // TODO: Decide whether to remove this - v.logger.Info("failed authz info for request", "resource", pretty.Sprint(v.res), "user_id", ret.UserId, "action", v.act.String()) + err := event.WriteObservation(ctx, op, + event.WithHeader( + "auth-results", struct { + Msg string `json:"msg"` + Resource *perms.Resource `json:"resource"` + UserId string `json:"user_id"` + Action string `json:"action"` + }{ + Msg: "failed authz info for request", + Resource: v.res, + UserId: ret.UserId, + Action: v.act.String(), + })) + if err != nil { + event.WriteError(ctx, op, err) + } } else { // If the anon user was used (either no token, or invalid (perhaps // expired) token), return a 401. That way if it's an authn'd user @@ -275,7 +292,8 @@ func Verify(ctx context.Context, opt ...Option) (ret VerifyResults) { return } -func (v *verifier) decryptToken() { +func (v *verifier) decryptToken(ctx context.Context) { + const op = "auth.(verifier).decryptToken" switch v.requestInfo.TokenFormat { case AuthTokenTypeUnknown: // Nothing to decrypt @@ -283,33 +301,33 @@ func (v *verifier) decryptToken() { case AuthTokenTypeBearer, AuthTokenTypeSplitCookie: if v.kms == nil { - v.logger.Trace("decrypt token: no KMS object available to authz system") + event.WriteError(ctx, op, stderrors.New("no KMS object available to authz system")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } tokenRepo, err := v.authTokenRepoFn() if err != nil { - v.logger.Warn("decrypt bearer token: failed to get authtoken repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("failed to get authtoken repo")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } at, err := tokenRepo.LookupAuthToken(v.ctx, v.requestInfo.PublicId) if err != nil { - v.logger.Trace("decrypt bearer token: failed to look up auth token by public ID", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("failed to look up auth token by public ID")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } if at == nil { - v.logger.Trace("decrypt bearer token: nil result from looking up auth token by public ID") + event.WriteError(ctx, op, stderrors.New("nil result from looking up auth token by public ID")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } tokenWrapper, err := v.kms.GetWrapper(v.ctx, at.GetScopeId(), kms.KeyPurposeTokens) if err != nil { - v.logger.Warn("decrypt bearer token: unable to get wrapper for tokens; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to get wrapper for tokens; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } @@ -318,40 +336,40 @@ func (v *verifier) decryptToken() { switch version { case globals.ServiceTokenV1: default: - v.logger.Trace("decrypt bearer token: unknown token encryption version; continuing as anonymous user", "version", version) + event.WriteError(ctx, op, stderrors.New("unknown token encryption version; continuing as anonymous user"), event.WithInfo("version", version)) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } marshaledToken, err := base58.FastBase58Decoding(v.requestInfo.EncryptedToken[len(globals.ServiceTokenV1):]) if err != nil { - v.logger.Trace("decrypt bearer token: error unmarshaling base58 token; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error unmarshaling base58 token; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } blobInfo := new(wrapping.EncryptedBlobInfo) if err := proto.Unmarshal(marshaledToken, blobInfo); err != nil { - v.logger.Trace("decrypt bearer token: error decoding encrypted token; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error decoding encrypted token; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } s1Bytes, err := tokenWrapper.Decrypt(v.ctx, blobInfo, []byte(v.requestInfo.PublicId)) if err != nil { - v.logger.Trace("decrypt bearer token: error decrypting encrypted token; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error decrypting encrypted token; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } var s1Info tokens.S1TokenInfo if err := proto.Unmarshal(s1Bytes, &s1Info); err != nil { - v.logger.Trace("decrypt bearer token: error unmarshaling token info; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error unmarshaling token info; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } if v.requestInfo.TokenFormat == AuthTokenTypeUnknown || s1Info.Token == "" || v.requestInfo.PublicId == "" { - v.logger.Trace("decrypt bearer token: after parsing, could not find valid token; continuing as anonymous user") + event.WriteError(ctx, op, stderrors.New("after parsing, could not find valid token; continuing as anonymous user")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } @@ -361,19 +379,19 @@ func (v *verifier) decryptToken() { case AuthTokenTypeRecoveryKms: if v.kms == nil { - v.logger.Trace("decrypt recovery token: no KMS object available to authz system") + event.WriteError(ctx, op, stderrors.New("no KMS object available to authz system")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } wrapper := v.kms.GetExternalWrappers().Recovery() if wrapper == nil { - v.logger.Trace("decrypt recovery token: no recovery KMS is available") + event.WriteError(ctx, op, stderrors.New("no recovery KMS is available")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } info, err := recovery.ParseRecoveryToken(v.ctx, wrapper, v.requestInfo.EncryptedToken) if err != nil { - v.logger.Trace("decrypt recovery token: error parsing and validating recovery token", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("decrypt recovery token: error parsing and validating recovery token")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } @@ -381,26 +399,26 @@ func (v *verifier) decryptToken() { // verified is before the current time, with a minute of fudging), and // it's before now, it's expired and might be a replay. if info.CreationTime.Add(globals.RecoveryTokenValidityPeriod).Before(time.Now()) { - v.logger.Warn("decrypt recovery token: recovery token has expired (possible replay attack)") + event.WriteError(ctx, op, stderrors.New("recovery token has expired (possible replay attack)")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } repo, err := v.serversRepoFn() if err != nil { - v.logger.Trace("decrypt recovery token: error fetching servers repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("decrypt recovery token: error fetching servers repo")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } if err := repo.AddRecoveryNonce(v.ctx, info.Nonce); err != nil { - v.logger.Warn("decrypt recovery token: error adding nonce to database (possible replay attack)", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("decrypt recovery token: error adding nonce to database (possible replay attack)")) v.requestInfo.TokenFormat = AuthTokenTypeUnknown return } - v.logger.Warn("recovery KMS was used to authorize a call", "url", v.requestInfo.Path, "method", v.requestInfo.Method) + event.WriteError(ctx, op, stderrors.New("recovery KMS was used to authorize a call"), event.WithInfo("url", v.requestInfo.Path, "method", v.requestInfo.Method)) } } -func (v verifier) performAuthCheck() (aclResults perms.ACLResults, userId string, scopeInfo *scopes.ScopeInfo, retAcl perms.ACL, retErr error) { +func (v verifier) performAuthCheck(ctx context.Context) (aclResults perms.ACLResults, userId string, scopeInfo *scopes.ScopeInfo, retAcl perms.ACL, retErr error) { const op = "auth.(verifier).performAuthCheck" // Ensure we return an error by default if we forget to set this somewhere retErr = errors.New(errors.Unknown, op, "default auth error") @@ -434,14 +452,14 @@ func (v verifier) performAuthCheck() (aclResults perms.ACLResults, userId string if err != nil { // Continue as the anonymous user as maybe this token is expired but // we can still perform the action - v.logger.Error("perform auth check: error validating token; continuing as anonymous user", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error validating token; continuing as anonymous user")) break } if at != nil { accountId = at.GetAuthAccountId() userId = at.GetIamUserId() if userId == "" { - v.logger.Warn("perform auth check: valid token did not map to a user, likely because no account is associated with the user any longer; continuing as u_anon", "token_id", at.GetPublicId()) + event.WriteError(ctx, op, stderrors.New("perform auth check: valid token did not map to a user, likely because no account is associated with the user any longer; continuing as u_anon"), event.WithInfo("token_id", at.GetPublicId())) userId = AnonymousUserId accountId = "" } @@ -597,7 +615,8 @@ func (r *VerifyResults) FetchOutputFields(res perms.Resource, act action.Type) p // split cookies and parses it. If it cannot be parsed successfully, the issue // is logged and we return blank, so logic will continue as the anonymous user. // The public ID and _encrypted_ token are returned along with the token format. -func GetTokenFromRequest(logger hclog.Logger, kmsCache *kms.Kms, req *http.Request) (string, string, TokenFormat) { +func GetTokenFromRequest(ctx context.Context, kmsCache *kms.Kms, req *http.Request) (string, string, TokenFormat) { + const op = "auth.GetTokenFromRequest" // First, get the token, either from the authorization header or from split // cookies var receivedTokenType TokenFormat @@ -637,7 +656,7 @@ func GetTokenFromRequest(logger hclog.Logger, kmsCache *kms.Kms, req *http.Reque splitFullToken := strings.Split(fullToken, "_") if len(splitFullToken) != 3 { - logger.Trace("get token from request: unexpected number of segments in token; continuing as anonymous user", "expected", 3, "found", len(splitFullToken)) + event.WriteError(ctx, op, stderrors.New("unexpected number of segments in token; continuing as anonymous user"), event.WithInfo("expected", 3, "found", len(splitFullToken))) return "", "", AuthTokenTypeUnknown } diff --git a/internal/servers/controller/auth/auth_test.go b/internal/servers/controller/auth/auth_test.go index 0fac71d13..981a6767a 100644 --- a/internal/servers/controller/auth/auth_test.go +++ b/internal/servers/controller/auth/auth_test.go @@ -113,7 +113,7 @@ func TestAuthTokenAuthenticator(t *testing.T) { Path: req.URL.Path, Method: req.Method, } - requestInfo.PublicId, requestInfo.EncryptedToken, requestInfo.TokenFormat = GetTokenFromRequest(logger, kms, req) + requestInfo.PublicId, requestInfo.EncryptedToken, requestInfo.TokenFormat = GetTokenFromRequest(context.TODO(), kms, req) assert.Equal(t, tc.tokenFormat, requestInfo.TokenFormat) if tc.userId == "" { @@ -125,7 +125,7 @@ func TestAuthTokenAuthenticator(t *testing.T) { require.True(t, ok) require.NotNil(t, v) - v.decryptToken() + v.decryptToken(context.TODO()) at, err := tokenRepo.ValidateToken(ctx, v.requestInfo.PublicId, v.requestInfo.Token) require.NoError(t, err) diff --git a/internal/servers/controller/controller.go b/internal/servers/controller/controller.go index 29f00aeef..8a0c5cf2b 100644 --- a/internal/servers/controller/controller.go +++ b/internal/servers/controller/controller.go @@ -15,6 +15,7 @@ import ( "github.com/hashicorp/boundary/internal/host/static" "github.com/hashicorp/boundary/internal/iam" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/scheduler" "github.com/hashicorp/boundary/internal/scheduler/job" "github.com/hashicorp/boundary/internal/servers" @@ -35,6 +36,9 @@ type Controller struct { baseCancel context.CancelFunc started *ua.Bool + tickerWg sync.WaitGroup + schedulerWg sync.WaitGroup + workerAuthCache *cache.Cache // Used for testing and tracking worker health @@ -156,26 +160,43 @@ func New(conf *Config) (*Controller, error) { } func (c *Controller) Start() error { + const op = "controller.(Controller).Start" if c.started.Load() { - c.logger.Info("already started, skipping") + event.WriteSysEvent(context.TODO(), op, "already started, skipping") return nil } c.baseContext, c.baseCancel = context.WithCancel(context.Background()) if err := c.registerJobs(); err != nil { return fmt.Errorf("error registering jobs: %w", err) } - if err := c.scheduler.Start(c.baseContext); err != nil { + if err := c.scheduler.Start(c.baseContext, &c.schedulerWg); err != nil { return fmt.Errorf("error starting scheduler: %w", err) } if err := c.startListeners(); err != nil { return fmt.Errorf("error starting controller listeners: %w", err) } - c.startStatusTicking(c.baseContext) - c.startRecoveryNonceCleanupTicking(c.baseContext) - c.startTerminateCompletedSessionsTicking(c.baseContext) - c.startCloseExpiredPendingTokens(c.baseContext) - c.started.Store(true) + c.tickerWg.Add(5) + go func() { + defer c.tickerWg.Done() + c.startStatusTicking(c.baseContext) + }() + go func() { + defer c.tickerWg.Done() + c.startRecoveryNonceCleanupTicking(c.baseContext) + }() + go func() { + defer c.tickerWg.Done() + c.startTerminateCompletedSessionsTicking(c.baseContext) + }() + go func() { + defer c.tickerWg.Done() + c.startCloseExpiredPendingTokens(c.baseContext) + }() + go func() { + defer c.tickerWg.Done() + c.started.Store(true) + }() return nil } @@ -208,15 +229,17 @@ func (c *Controller) registerSessionCleanupJob() error { } func (c *Controller) Shutdown(serversOnly bool) error { + const op = "controller.(Controller).Shutdown" if !c.started.Load() { - c.logger.Info("already shut down, skipping") - return nil + event.WriteSysEvent(context.TODO(), op, "already shut down, skipping") } + defer c.started.Store(false) c.baseCancel() if err := c.stopListeners(serversOnly); err != nil { return fmt.Errorf("error stopping controller listeners: %w", err) } - c.started.Store(false) + c.schedulerWg.Wait() + c.tickerWg.Wait() if c.conf.Eventer != nil { if err := c.conf.Eventer.FlushNodes(context.Background()); err != nil { return fmt.Errorf("error flushing controller eventer nodes: %w", err) diff --git a/internal/servers/controller/handler.go b/internal/servers/controller/handler.go index 5ea4ce2cb..ecd0e64e2 100644 --- a/internal/servers/controller/handler.go +++ b/internal/servers/controller/handler.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "encoding/json" + "errors" "fmt" "io/ioutil" "net/http" @@ -16,6 +17,7 @@ import ( "github.com/hashicorp/boundary/globals" "github.com/hashicorp/boundary/internal/auth/oidc" "github.com/hashicorp/boundary/internal/gen/controller/api/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/requests" "github.com/hashicorp/boundary/internal/servers/common" "github.com/hashicorp/boundary/internal/servers/controller/auth" @@ -64,7 +66,7 @@ func (c *Controller) handler(props HandlerProperties) (http.Handler, error) { commonWrappedHandler := wrapHandlerWithCommonFuncs(corsWrappedHandler, c, props) callbackInterceptingHandler := wrapHandlerWithCallbackInterceptor(commonWrappedHandler, c) printablePathCheckHandler := cleanhttp.PrintablePathCheckHandler(callbackInterceptingHandler, nil) - eventsHandler, err := common.WrapWithEventsHandler(printablePathCheckHandler, c.conf.Eventer, c.logger, c.kms) + eventsHandler, err := common.WrapWithEventsHandler(printablePathCheckHandler, c.conf.Eventer, c.kms) if err != nil { return nil, err } @@ -200,6 +202,7 @@ func handleGrpcGateway(c *Controller, props HandlerProperties) (http.Handler, er } func wrapHandlerWithCommonFuncs(h http.Handler, c *Controller, props HandlerProperties) http.Handler { + const op = "controller.wrapHandlerWithCommonFuncs" var maxRequestDuration time.Duration var maxRequestSize int64 if props.ListenerConfig != nil { @@ -213,19 +216,13 @@ func wrapHandlerWithCommonFuncs(h http.Handler, c *Controller, props HandlerProp maxRequestSize = globals.DefaultMaxRequestSize } - logUrls := os.Getenv("BOUNDARY_LOG_URLS") != "" - disableAuthzFailures := c.conf.DisableAuthorizationFailures || (c.conf.RawConfig.DevController && os.Getenv("BOUNDARY_DEV_SKIP_AUTHZ") != "") if disableAuthzFailures { - c.logger.Warn("AUTHORIZATION CHECKING DISABLED") + event.WriteSysEvent(context.TODO(), op, "AUTHORIZATION CHECKING DISABLED") } return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - if logUrls { - c.logger.Trace("request received", "method", r.Method, "url", r.URL.RequestURI()) - } - // Set the Cache-Control header for all responses returned w.Header().Set("Cache-Control", "no-store") @@ -245,7 +242,7 @@ func wrapHandlerWithCommonFuncs(h http.Handler, c *Controller, props HandlerProp DisableAuthzFailures: disableAuthzFailures, } - requestInfo.PublicId, requestInfo.EncryptedToken, requestInfo.TokenFormat = auth.GetTokenFromRequest(c.logger, c.kms, r) + requestInfo.PublicId, requestInfo.EncryptedToken, requestInfo.TokenFormat = auth.GetTokenFromRequest(ctx, c.kms, r) ctx = auth.NewVerifierContext(ctx, c.logger, c.IamRepoFn, c.AuthTokenRepoFn, c.ServersRepoFn, c.kms, requestInfo) // Add general request information to the context. The information from @@ -318,7 +315,7 @@ func wrapHandlerWithCors(h http.Handler, props HandlerProperties) http.Handler { err := handlers.ApiErrorWithCodeAndMessage(codes.PermissionDenied, "origin forbidden") enc := json.NewEncoder(w) - enc.Encode(err) + _ = enc.Encode(err) return } @@ -353,6 +350,28 @@ func wrapHandlerWithCallbackInterceptor(h http.Handler, c *Controller) http.Hand logCallbackErrors := os.Getenv("BOUNDARY_LOG_CALLBACK_ERRORS") != "" return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { + const op = "controller.wrapHandlerWithCallbackInterceptor" + ctx := req.Context() + var err error + id, err := event.NewId(event.IdField) + if err != nil { + w.WriteHeader(http.StatusInternalServerError) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to create id for event", "method", req.Method, "url", req.URL.RequestURI())) + return + } + info := &event.RequestInfo{ + EventId: id, + Id: common.GeneratedTraceId(ctx), + PublicId: "unknown", + Method: req.Method, + Path: req.URL.RequestURI(), + } + ctx, err = event.NewRequestInfoContext(ctx, info) + if err != nil { + w.WriteHeader(http.StatusInternalServerError) + event.WriteError(req.Context(), op, err, event.WithInfoMsg("unable to create context with request info", "method", req.Method, "url", req.URL.RequestURI())) + return + } // If this doesn't have a callback suffix on a supported action, serve // normally if !strings.HasSuffix(req.URL.Path, ":authenticate:callback") { @@ -373,7 +392,7 @@ func wrapHandlerWithCallbackInterceptor(h http.Handler, c *Controller) http.Hand case http.MethodGet: if err := req.ParseForm(); err != nil { if logCallbackErrors && c != nil { - c.logger.Trace("callback error", "method", req.Method, "url", req.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("callback error")) } w.WriteHeader(http.StatusBadRequest) return @@ -399,19 +418,19 @@ func wrapHandlerWithCallbackInterceptor(h http.Handler, c *Controller) http.Hand if s, ok := values["state"].(string); ok { stateWrapper, err := oidc.UnwrapMessage(context.Background(), s) if err != nil { - c.logger.Trace("callback error marshaling state", "method", req.Method, "url", req.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error marshaling state")) w.WriteHeader(http.StatusInternalServerError) return } if stateWrapper.AuthMethodId == "" { - c.logger.Trace("callback error: missing auth method id", "method", req.Method, "url", req.URL.RequestURI()) + event.WriteError(ctx, op, err, event.WithInfoMsg("missing auth method id")) w.WriteHeader(http.StatusInternalServerError) return } stripped := strings.TrimSuffix(req.URL.Path, "oidc:authenticate") req.URL.Path = fmt.Sprintf("%s%s:authenticate", stripped, stateWrapper.AuthMethodId) } else { - c.logger.Trace("callback error: missing state parameter", "method", req.Method, "url", req.URL.RequestURI()) + event.WriteError(ctx, op, errors.New("missing state parameter")) w.WriteHeader(http.StatusInternalServerError) return } @@ -422,7 +441,7 @@ func wrapHandlerWithCallbackInterceptor(h http.Handler, c *Controller) http.Hand attrBytes, err := json.Marshal(attrs) if err != nil { if logCallbackErrors && c != nil { - c.logger.Trace("callback error marshaling json", "method", req.Method, "url", req.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error marshaling json")) } w.WriteHeader(http.StatusInternalServerError) return @@ -434,7 +453,7 @@ func wrapHandlerWithCallbackInterceptor(h http.Handler, c *Controller) http.Hand if req.Body != nil { if err := req.Body.Close(); err != nil { if logCallbackErrors && c != nil { - c.logger.Trace("callback error closing original request body", "method", req.Method, "url", req.URL.RequestURI(), "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing original request body")) } } } diff --git a/internal/servers/controller/handler_noui.go b/internal/servers/controller/handler_noui.go index 292baea44..c7bf5ca0c 100644 --- a/internal/servers/controller/handler_noui.go +++ b/internal/servers/controller/handler_noui.go @@ -1,13 +1,17 @@ package controller import ( + "context" "net/http" "path/filepath" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" ) func devPassthroughHandler(logger hclog.Logger, passthroughDir string) http.Handler { + const op = "controller.devPassthroughHandler" + ctx := context.TODO() // Panic may not be ideal but this is never a production call and it'll // panic on startup. We could also just change the function to return // an error. @@ -15,7 +19,7 @@ func devPassthroughHandler(logger hclog.Logger, passthroughDir string) http.Hand if err != nil { panic(err) } - logger.Warn("serving passthrough files at /", "path", abs) + event.WriteSysEvent(ctx, op, "serving passthrough files at /", "path", abs) fs := http.FileServer(http.Dir(abs)) prefixHandler := http.StripPrefix("/", fs) diff --git a/internal/servers/controller/handlers/authmethods/oidc.go b/internal/servers/controller/handlers/authmethods/oidc.go index 3f9f93ce9..a127e0e4e 100644 --- a/internal/servers/controller/handlers/authmethods/oidc.go +++ b/internal/servers/controller/handlers/authmethods/oidc.go @@ -12,6 +12,7 @@ import ( "github.com/hashicorp/boundary/internal/errors" pb "github.com/hashicorp/boundary/internal/gen/controller/api/resources/authmethods" pbs "github.com/hashicorp/boundary/internal/gen/controller/api/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers/controller/auth" "github.com/hashicorp/boundary/internal/servers/controller/handlers" "github.com/hashicorp/boundary/internal/types/action" @@ -178,9 +179,9 @@ func (s Service) authenticateOidcStart(ctx context.Context, req *pbs.Authenticat authUrl, tokenId, err := oidc.StartAuth(ctx, s.oidcRepoFn, req.GetAuthMethodId(), opts...) if err != nil { - if s.oidcLogger != nil { - s.oidcLogger.Error("error starting the oidc authentication flow", "op", op, "error", err) - } + // this event.WriteError(...) may cause a dup error to be emitted... + // it should be removed if that's the case. + event.WriteError(ctx, op, err, event.WithInfoMsg("error starting the oidc authentication flow")) return nil, errors.New(errors.Internal, op, "Error generating parameters for starting the OIDC flow. See the controller's log for more information.") } @@ -305,9 +306,9 @@ func (s Service) authenticateOidcToken(ctx context.Context, req *pbs.Authenticat case errors.Match(errors.T(errors.AuthAttemptExpired), err): return nil, errors.Wrap(err, op, errors.WithMsg("Forbidden.")) default: - if s.oidcLogger != nil { - s.oidcLogger.Error("error generating parameters for token request", "op", op, "error", err) - } + // this event.WriteError(...) may cause a dup error to be emitted... + // it should be removed if that's the case. + event.WriteError(ctx, op, err, event.WithInfoMsg("error generating parameters for token request")) return nil, errors.Wrap(err, op, errors.WithMsg("Error generating parameters for token request. See the controller's log for more information.")) } } diff --git a/internal/servers/controller/handlers/errors.go b/internal/servers/controller/handlers/errors.go index 581a0dc3a..12ee34251 100644 --- a/internal/servers/controller/handlers/errors.go +++ b/internal/servers/controller/handlers/errors.go @@ -11,6 +11,7 @@ import ( "github.com/grpc-ecosystem/grpc-gateway/v2/runtime" "github.com/hashicorp/boundary/internal/errors" pb "github.com/hashicorp/boundary/internal/gen/controller/api" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" "google.golang.org/grpc/codes" "google.golang.org/grpc/status" @@ -115,10 +116,12 @@ func UnauthenticatedError() error { } func InvalidArgumentErrorf(msg string, fields map[string]string) *apiError { + const op = "handlers.InvalidArgumentErrorf" + ctx := context.TODO() err := ApiErrorWithCodeAndMessage(codes.InvalidArgument, msg) var apiErr *apiError if !errors.As(err, &apiErr) { - hclog.L().Error("Unable to build invalid argument api error.", "original error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("Unable to build invalid argument api error.")) } if len(fields) > 0 { @@ -183,6 +186,7 @@ func backendErrorToApiError(inErr error) *apiError { } func ErrorHandler(logger hclog.Logger) runtime.ErrorHandlerFunc { + const op = "handlers.ErrorHandler" const errorFallback = `{"error": "failed to marshal error message"}` return func(ctx context.Context, _ *runtime.ServeMux, mar runtime.Marshaler, w http.ResponseWriter, r *http.Request, inErr error) { // API specified error, otherwise we need to translate repo/db errors. @@ -190,20 +194,20 @@ func ErrorHandler(logger hclog.Logger) runtime.ErrorHandlerFunc { isApiErr := errors.As(inErr, &apiErr) if !isApiErr { if err := backendErrorToApiError(inErr); err != nil && !errors.As(err, &apiErr) { - logger.Error("failed to cast error to api error", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("failed to cast error to api error")) } } if apiErr.status == http.StatusInternalServerError { - logger.Error("internal error returned", "error", inErr) + event.WriteError(ctx, op, inErr, event.WithInfoMsg("internal error returned")) } buf, merr := mar.Marshal(apiErr.inner) if merr != nil { - logger.Error("failed to marshal error response", "response", fmt.Sprintf("%#v", apiErr.inner), "error", merr) + event.WriteError(ctx, op, merr, event.WithInfoMsg("failed to marshal error response", "response", fmt.Sprintf("%#v", apiErr.inner))) w.WriteHeader(http.StatusInternalServerError) if _, err := io.WriteString(w, errorFallback); err != nil { - logger.Error("failed to write response", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("failed to write response")) } return } @@ -211,7 +215,7 @@ func ErrorHandler(logger hclog.Logger) runtime.ErrorHandlerFunc { w.Header().Set("Content-Type", mar.ContentType(apiErr.inner)) w.WriteHeader(int(apiErr.status)) if _, err := w.Write(buf); err != nil { - logger.Error("failed to send response chunk", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("failed to send response chunk")) return } } diff --git a/internal/servers/controller/handlers/workers/worker_service.go b/internal/servers/controller/handlers/workers/worker_service.go index 56520a03f..0390489f0 100644 --- a/internal/servers/controller/handlers/workers/worker_service.go +++ b/internal/servers/controller/handlers/workers/worker_service.go @@ -2,6 +2,7 @@ package workers import ( "context" + "errors" "fmt" "sync" "time" @@ -9,6 +10,7 @@ import ( "github.com/hashicorp/boundary/internal/gen/controller/api/resources/targets" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers" "github.com/hashicorp/boundary/internal/servers/controller/common" "github.com/hashicorp/boundary/internal/servers/controller/handlers" @@ -52,24 +54,24 @@ var ( ) func (ws *workerServiceServer) Status(ctx context.Context, req *pbs.StatusRequest) (*pbs.StatusResponse, error) { + const op = "workers.(workerServiceServer).Status" // TODO: on the worker, if we get errors back from this repeatedly, do we // terminate all sessions since we can't know if they were canceled? - ws.logger.Trace("got status request from worker", "name", req.Worker.PrivateId, "address", req.Worker.Address, "jobs", req.GetJobs()) ws.updateTimes.Store(req.Worker.PrivateId, time.Now()) serverRepo, err := ws.serversRepoFn() if err != nil { - ws.logger.Error("error getting servers repo", "error", err) - return &pbs.StatusResponse{}, status.Errorf(codes.Internal, "Error aqcuiring repo to store worker status: %v", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error getting servers repo")) + return &pbs.StatusResponse{}, status.Errorf(codes.Internal, "Error acquiring repo to store worker status: %v", err) } sessRepo, err := ws.sessionRepoFn() if err != nil { - ws.logger.Error("error getting sessions repo", "error", err) - return &pbs.StatusResponse{}, status.Errorf(codes.Internal, "Error aqcuiring repo to query session status: %v", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error getting sessions repo")) + return &pbs.StatusResponse{}, status.Errorf(codes.Internal, "Error acquiring repo to query session status: %v", err) } req.Worker.Type = resource.Worker.String() controllers, _, err := serverRepo.UpsertServer(ctx, req.Worker, servers.WithUpdateTags(req.GetUpdateTags())) if err != nil { - ws.logger.Error("error storing worker status", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error storing worker status")) return &pbs.StatusResponse{}, status.Errorf(codes.Internal, "Error storing worker status: %v", err) } ret := &pbs.StatusResponse{ @@ -209,14 +211,15 @@ func (ws *workerServiceServer) Status(ctx context.Context, req *pbs.StatusReques return nil, status.Errorf(codes.Internal, "Error closing dead conns for worker %s: %v", req.Worker.PrivateId, err) } if closedConns > 0 { - ws.logger.Info("marked unclaimed connections as closed", "server_id", req.Worker.PrivateId, "count", closedConns) + event.WriteSysEvent(ctx, op, "marked unclaimed connections as closed", "server_id", req.Worker.PrivateId, "count", closedConns) } return ret, nil } func (ws *workerServiceServer) LookupSession(ctx context.Context, req *pbs.LookupSessionRequest) (*pbs.LookupSessionResponse, error) { - ws.logger.Trace("got validate session request from worker", "session_id", req.GetSessionId()) + const op = "workers.(workerServiceServer).LookupSession" + event.WriteSysEvent(ctx, op, "got validate session request from worker", "session_id", req.GetSessionId()) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -236,17 +239,17 @@ func (ws *workerServiceServer) LookupSession(ctx context.Context, req *pbs.Looku if sessionInfo.WorkerFilter != "" { if req.ServerId == "" { - ws.logger.Error("worker filter enabled for session but got no server ID from worker") + event.WriteError(ctx, op, errors.New("worker filter enabled for session but got no server ID from worker")) return &pbs.LookupSessionResponse{}, status.Errorf(codes.Internal, "Did not receive server ID when looking up session but filtering is enabled: %v", err) } serversRepo, err := ws.serversRepoFn() if err != nil { - ws.logger.Error("error getting servers repo", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error getting servers repo")) return &pbs.LookupSessionResponse{}, status.Errorf(codes.Internal, "Error acquiring server repo when looking up session: %v", err) } tags, err := serversRepo.ListTagsForServers(ctx, []string{req.ServerId}) if err != nil { - ws.logger.Error("error looking up tags for server", "error", err, "server_id", req.ServerId) + event.WriteError(ctx, op, err, event.WithInfoMsg("error looking up tags for server", "server_id", req.ServerId)) return &pbs.LookupSessionResponse{}, status.Errorf(codes.Internal, "Error looking up tags for server: %v", err) } // Build the map for filtering. @@ -260,7 +263,7 @@ func (ws *workerServiceServer) LookupSession(ctx context.Context, req *pbs.Looku // Create the evaluator eval, err := bexpr.CreateEvaluator(sessionInfo.WorkerFilter) if err != nil { - ws.logger.Error("error creating worker filter evaluator", "error", err, "server_id", req.ServerId) + event.WriteError(ctx, op, err, event.WithInfoMsg("error creating worker filter evaluator", "server_id", req.ServerId)) return &pbs.LookupSessionResponse{}, status.Errorf(codes.Internal, "Error creating worker filter evaluator: %v", err) } filterInput := map[string]interface{}{ @@ -316,7 +319,8 @@ func (ws *workerServiceServer) LookupSession(ctx context.Context, req *pbs.Looku } func (ws *workerServiceServer) CancelSession(ctx context.Context, req *pbs.CancelSessionRequest) (*pbs.CancelSessionResponse, error) { - ws.logger.Trace("got cancel session request from worker", "session_id", req.GetSessionId()) + const op = "workers.(workerServiceServer).CancelSession" + event.WriteSysEvent(ctx, op, "got cancel session request from worker", "session_id", req.GetSessionId()) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -339,7 +343,8 @@ func (ws *workerServiceServer) CancelSession(ctx context.Context, req *pbs.Cance } func (ws *workerServiceServer) ActivateSession(ctx context.Context, req *pbs.ActivateSessionRequest) (*pbs.ActivateSessionResponse, error) { - ws.logger.Trace("got activate session request from worker", "session_id", req.GetSessionId()) + const op = "workers.(workerServiceServer).ActivateSession" + event.WriteSysEvent(ctx, op, "got activate session request from worker", "session_id", req.GetSessionId()) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -363,12 +368,13 @@ func (ws *workerServiceServer) ActivateSession(ctx context.Context, req *pbs.Act return nil, status.Error(codes.Internal, "Invalid session state in activate response.") } - ws.logger.Info("session activated", + event.WriteSysEvent(ctx, op, "session activated", "session_id", sessionInfo.PublicId, "target_id", sessionInfo.TargetId, "user_id", sessionInfo.UserId, "host_set_id", sessionInfo.HostSetId, - "host_id", sessionInfo.HostId) + "host_id", sessionInfo.HostId, + ) return &pbs.ActivateSessionResponse{ Status: sessionStates[0].Status.ProtoVal(), @@ -376,7 +382,8 @@ func (ws *workerServiceServer) ActivateSession(ctx context.Context, req *pbs.Act } func (ws *workerServiceServer) AuthorizeConnection(ctx context.Context, req *pbs.AuthorizeConnectionRequest) (*pbs.AuthorizeConnectionResponse, error) { - ws.logger.Trace("got authorize connection request from worker", "session_id", req.GetSessionId()) + const op = "workers.(workerServiceServer" + event.WriteSysEvent(ctx, op, "got authorize connection request from worker", "session_id", req.GetSessionId()) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -403,16 +410,18 @@ func (ws *workerServiceServer) AuthorizeConnection(ctx context.Context, req *pbs ret.ConnectionsLeft -= int32(authzSummary.CurrentConnectionCount) } - ws.logger.Info("authorized connection", + event.WriteSysEvent(ctx, op, "authorized connection", "session_id", req.GetSessionId(), "connection_id", ret.ConnectionId, - "connections_left", ret.ConnectionsLeft) + "connections_left", ret.ConnectionsLeft, + ) return ret, nil } func (ws *workerServiceServer) ConnectConnection(ctx context.Context, req *pbs.ConnectConnectionRequest) (*pbs.ConnectConnectionResponse, error) { - ws.logger.Trace("got connection established information from worker", "connection_id", req.GetConnectionId()) + const op = "workers.(workerServiceServer).ConnectConnection" + event.WriteSysEvent(ctx, op, "got connection established information from worker", "connection_id", req.GetConnectionId()) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -451,12 +460,13 @@ func (ws *workerServiceServer) ConnectConnection(ctx context.Context, req *pbs.C ) } - ws.logger.Info("connection established", loggerPairs...) + event.WriteSysEvent(ctx, op, "connection established", "logger_pairs", loggerPairs) return ret, nil } func (ws *workerServiceServer) CloseConnection(ctx context.Context, req *pbs.CloseConnectionRequest) (*pbs.CloseConnectionResponse, error) { + const op = "workers.(workerServiceServer).CloseConnection" numCloses := len(req.GetCloseRequestData()) if numCloses == 0 { return &pbs.CloseConnectionResponse{}, nil @@ -474,7 +484,7 @@ func (ws *workerServiceServer) CloseConnection(ctx context.Context, req *pbs.Clo ClosedReason: session.ClosedReason(v.GetReason()), }) } - ws.logger.Trace("got connection close information from worker", "connection_ids", closeIds) + event.WriteSysEvent(ctx, op, "got connection close information from worker", "connection_ids", closeIds) sessRepo, err := ws.sessionRepoFn() if err != nil { @@ -504,7 +514,7 @@ func (ws *workerServiceServer) CloseConnection(ctx context.Context, req *pbs.Clo } for _, v := range req.GetCloseRequestData() { - ws.logger.Info("connection closed", "connection_id", v.ConnectionId) + event.WriteSysEvent(ctx, op, "connection closed", "connection_id", v.ConnectionId) } ret := &pbs.CloseConnectionResponse{ diff --git a/internal/servers/controller/intercepting_listener.go b/internal/servers/controller/intercepting_listener.go index ed948a6e7..a22eac92f 100644 --- a/internal/servers/controller/intercepting_listener.go +++ b/internal/servers/controller/intercepting_listener.go @@ -1,9 +1,12 @@ package controller import ( + "context" "errors" "fmt" "net" + + "github.com/hashicorp/boundary/internal/observability/event" ) // interceptingListener allows us to validate the nonce from a connection before @@ -41,42 +44,42 @@ func newInterceptingListener(c *Controller, baseLn net.Listener) *interceptingLi } func (m *interceptingListener) Accept() (net.Conn, error) { + const op = "controller.(interceptingListener).Accept" + ctx := context.TODO() conn, err := m.baseLn.Accept() if err != nil { if conn != nil { if err := conn.Close(); err != nil { - m.c.logger.Error("error closing worker connection", "error", err) + event.WriteError(context.TODO(), op, err, event.WithInfoMsg("error closing worker connection")) } } return nil, err } - if m.c.logger.IsTrace() { - m.c.logger.Trace("got connection", "addr", conn.RemoteAddr()) - } + nonce := make([]byte, 20) read, err := conn.Read(nonce) if err != nil { if err := conn.Close(); err != nil { - m.c.logger.Error("error closing worker connection", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing worker connection")) } return nil, fmt.Errorf("error reading nonce from connection: %w", err) } if read != len(nonce) { if err := conn.Close(); err != nil { - m.c.logger.Error("error closing worker connection", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing worker connection")) } return nil, fmt.Errorf("error reading nonce from worker, expected %d bytes, got %d", 20, read) } workerInfoRaw, found := m.c.workerAuthCache.Get(string(nonce)) if !found { if err := conn.Close(); err != nil { - m.c.logger.Error("error closing worker connection", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing worker connection")) } return nil, errors.New("did not find valid nonce for incoming worker") } workerInfo := workerInfoRaw.(*workerAuthEntry) workerInfo.conn = conn - m.c.logger.Info("worker successfully authed", "name", workerInfo.Name) + event.WriteSysEvent(ctx, op, "worker successfully authed", "name", workerInfo.Name) return conn, nil } diff --git a/internal/servers/controller/session_cleanup_job.go b/internal/servers/controller/session_cleanup_job.go index fd59e6fa8..2eea1794c 100644 --- a/internal/servers/controller/session_cleanup_job.go +++ b/internal/servers/controller/session_cleanup_job.go @@ -2,10 +2,12 @@ package controller import ( "context" + stderrors "errors" "fmt" "time" "github.com/hashicorp/boundary/internal/errors" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/scheduler" "github.com/hashicorp/boundary/internal/servers/controller/common" "github.com/hashicorp/boundary/internal/session" @@ -85,10 +87,6 @@ func (j *sessionCleanupJob) Status() scheduler.JobStatus { // Run executes the job. func (j *sessionCleanupJob) Run(ctx context.Context) error { const op = "controller.(sessionCleanupJob).Run" - j.logger.Debug( - "starting job", - "op", op, - ) j.totalClosed = 0 // Load repos. @@ -104,30 +102,19 @@ func (j *sessionCleanupJob) Run(ctx context.Context) error { } if len(results) < 1 { - j.logger.Debug( - "all workers OK, no connections to close", - "op", op, - ) } else { for _, result := range results { - // Log a closed connection message for each worker as a warning - j.logger.Warn( - "worker has not reported status within acceptable grace period, all connections closed", - "op", op, - "private_id", result.ServerId, - "update_time", result.LastUpdateTime, - "grace_period_seconds", j.gracePeriod, - "number_connections_closed", result.NumberConnectionsClosed, - ) + event.WriteError(ctx, op, stderrors.New("worker has not reported status within acceptable grace period, all connections closed"), + event.WithInfo( + "private_id", result.ServerId, + "update_time", result.LastUpdateTime, + "grace_period_seconds", j.gracePeriod, + "number_connections_closed", result.NumberConnectionsClosed, + )) j.totalClosed += result.NumberConnectionsClosed } } - j.logger.Debug( - "job finished", - "op", op, - "total_connections_closed", j.totalClosed, - ) return nil } diff --git a/internal/servers/controller/testing.go b/internal/servers/controller/testing.go index 3e97c6f53..f5a68e38c 100644 --- a/internal/servers/controller/testing.go +++ b/internal/servers/controller/testing.go @@ -20,6 +20,7 @@ import ( "github.com/hashicorp/boundary/internal/iam" "github.com/hashicorp/boundary/internal/intglobals" "github.com/hashicorp/boundary/internal/kms" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers" "github.com/hashicorp/go-hclog" wrapping "github.com/hashicorp/go-kms-wrapping" @@ -379,6 +380,7 @@ type TestControllerOpts struct { } func NewTestController(t *testing.T, opts *TestControllerOpts) *TestController { + const op = "controller.NewTestController" ctx, cancel := context.WithCancel(context.Background()) if opts == nil { @@ -465,7 +467,6 @@ func NewTestController(t *testing.T, opts *TestControllerOpts) *TestController { if err != nil { t.Fatal(err) } - tc.b.Logger.Info("controller name generated", "name", opts.Config.Controller.Name) } if err := tc.b.SetupEventing(tc.b.Logger, tc.b.StderrLock, opts.Config.Controller.Name, base.WithEventerConfig(opts.Config.Eventing)); err != nil { @@ -607,6 +608,7 @@ func NewTestController(t *testing.T, opts *TestControllerOpts) *TestController { } func (tc *TestController) AddClusterControllerMember(t *testing.T, opts *TestControllerOpts) *TestController { + const op = "controller.(TestController).AddClusterControllerMember" if opts == nil { opts = new(TestControllerOpts) } @@ -635,7 +637,7 @@ func (tc *TestController) AddClusterControllerMember(t *testing.T, opts *TestCon if err != nil { t.Fatal(err) } - nextOpts.Logger.Info("controller name generated", "name", nextOpts.Name) + event.WriteSysEvent(context.TODO(), op, "controller name generated", "name", nextOpts.Name) } return NewTestController(t, nextOpts) } @@ -644,7 +646,9 @@ func (tc *TestController) AddClusterControllerMember(t *testing.T, opts *TestCon // come in. If it does not come in within the default status grace // period, this function returns an error. func (tc *TestController) WaitForNextWorkerStatusUpdate(workerId string) error { - tc.Logger().Debug("waiting for next status report from worker", "worker", workerId) + const op = "controller.(TestController).WaitForNextWorkerStatusUpdate" + ctx := context.TODO() + event.WriteSysEvent(ctx, op, "waiting for next status report from worker", "worker", workerId) waitStatusStart := time.Now() ctx, cancel := context.WithTimeout(tc.ctx, tc.b.StatusGracePeriodDuration) defer cancel() @@ -701,10 +705,9 @@ func (tc *TestController) WaitForNextWorkerStatusUpdate(workerId string) error { } if err != nil { - tc.Logger().Error("error waiting for next status report from worker", "worker", workerId, "err", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error waiting for next status report from worker", "worker", workerId)) return err } - - tc.Logger().Debug("waiting for next status report from worker received successfully", "worker", workerId) + event.WriteSysEvent(ctx, op, "waiting for next status report from worker received successfully", "worker", workerId) return nil } diff --git a/internal/servers/controller/tickers.go b/internal/servers/controller/tickers.go index 82f9e46c9..f3873adb2 100644 --- a/internal/servers/controller/tickers.go +++ b/internal/servers/controller/tickers.go @@ -5,6 +5,7 @@ import ( "math/rand" "time" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers" "github.com/hashicorp/boundary/internal/types/resource" ) @@ -19,138 +20,133 @@ const ( var RecoveryNonceCleanupInterval = 2 * time.Minute func (c *Controller) startStatusTicking(cancelCtx context.Context) { - go func() { - timer := time.NewTimer(0) - for { - select { - case <-cancelCtx.Done(): - c.logger.Info("status ticking shutting down") - return + const op = "controller.(Controller).startStatusTicking" + timer := time.NewTimer(0) + for { + select { + case <-cancelCtx.Done(): + event.WriteSysEvent(cancelCtx, op, "status ticking shutting down") + return - case <-timer.C: - server := &servers.Server{ - PrivateId: c.conf.RawConfig.Controller.Name, - Name: c.conf.RawConfig.Controller.Name, - Type: resource.Controller.String(), - Description: c.conf.RawConfig.Controller.Description, - Address: c.conf.RawConfig.Controller.PublicClusterAddr, - } - repo, err := c.ServersRepoFn() - if err != nil { - c.logger.Error("error fetching repository for status update", "error", err) - } else { - _, _, err = repo.UpsertServer(cancelCtx, server) - if err != nil { - c.logger.Error("error performing status update", "error", err) - } else { - c.logger.Trace("controller status successfully saved") - } - } - timer.Reset(statusInterval) + case <-timer.C: + server := &servers.Server{ + PrivateId: c.conf.RawConfig.Controller.Name, + Name: c.conf.RawConfig.Controller.Name, + Type: resource.Controller.String(), + Description: c.conf.RawConfig.Controller.Description, + Address: c.conf.RawConfig.Controller.PublicClusterAddr, } + repo, err := c.ServersRepoFn() + if err != nil { + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error fetching repository for status update")) + } else { + _, _, err = repo.UpsertServer(cancelCtx, server) + if err != nil { + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error performing status update")) + } else { + } + } + timer.Reset(statusInterval) } - }() + } } func (c *Controller) startRecoveryNonceCleanupTicking(cancelCtx context.Context) { - go func() { - timer := time.NewTimer(0) - for { - select { - case <-cancelCtx.Done(): - c.logger.Info("recovery nonce ticking shutting down") - return + const op = "controller.(Controller).startRecoveryNonceCleanupTicking" + timer := time.NewTimer(0) + for { + select { + case <-cancelCtx.Done(): + event.WriteSysEvent(cancelCtx, op, "recovery nonce ticking shutting down") + return - case <-timer.C: - repo, err := c.ServersRepoFn() + case <-timer.C: + repo, err := c.ServersRepoFn() + if err != nil { + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error fetching repository for recovery nonce cleanup")) + } else { + nonceCount, err := repo.CleanupNonces(cancelCtx) if err != nil { - c.logger.Error("error fetching repository for recovery nonce cleanup", "error", err) - } else { - nonceCount, err := repo.CleanupNonces(cancelCtx) - if err != nil { - c.logger.Error("error performing recovery nonce cleanup", "error", err) - } else if nonceCount > 0 { - c.logger.Info("recovery nonce cleanup successful", "nonces_cleaned", nonceCount) - } + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error performing recovery nonce cleanup")) + } else if nonceCount > 0 { + event.WriteSysEvent(cancelCtx, op, "recovery nonce cleanup successful", "nonces_cleaned", nonceCount) } - timer.Reset(RecoveryNonceCleanupInterval) } + timer.Reset(RecoveryNonceCleanupInterval) } - }() + } } func (c *Controller) startTerminateCompletedSessionsTicking(cancelCtx context.Context) { - go func() { - r := rand.New(rand.NewSource(time.Now().UnixNano())) - // desynchronize calls from the controllers, to ease the load on the DB. - getRandomInterval := func() time.Duration { - // 0 to 0.5 adjustment to the base - f := r.Float64() / 2 - // Half a chance to be faster, not slower - if r.Float32() > 0.5 { - f = -1 * f - } - return terminationInterval + time.Duration(f*float64(time.Minute)) + const op = "controller.(Controller).startTerminateCompletedSessionsTicking" + r := rand.New(rand.NewSource(time.Now().UnixNano())) + // desynchronize calls from the controllers, to ease the load on the DB. + getRandomInterval := func() time.Duration { + // 0 to 0.5 adjustment to the base + f := r.Float64() / 2 + // Half a chance to be faster, not slower + if r.Float32() > 0.5 { + f = -1 * f } - timer := time.NewTimer(0) - for { - select { - case <-cancelCtx.Done(): - c.logger.Info("terminating completed sessions ticking shutting down") - return + return terminationInterval + time.Duration(f*float64(time.Minute)) + } + timer := time.NewTimer(0) + for { + select { + case <-cancelCtx.Done(): + event.WriteSysEvent(cancelCtx, op, "terminating completed sessions ticking shutting down") + return - case <-timer.C: - repo, err := c.SessionRepoFn() + case <-timer.C: + repo, err := c.SessionRepoFn() + if err != nil { + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error fetching repository for terminating completed sessions")) + } else { + terminationCount, err := repo.TerminateCompletedSessions(cancelCtx) if err != nil { - c.logger.Error("error fetching repository for terminating completed sessions", "error", err) - } else { - terminationCount, err := repo.TerminateCompletedSessions(cancelCtx) - if err != nil { - c.logger.Error("error performing termination of completed sessions", "error", err) - } else if terminationCount > 0 { - c.logger.Info("terminating completed sessions successful", "sessions_terminated", terminationCount) - } + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error performing termination of completed sessions")) + } else if terminationCount > 0 { + event.WriteSysEvent(cancelCtx, op, "terminating completed sessions successful", "sessions_terminated", terminationCount) } - timer.Reset(getRandomInterval()) } + timer.Reset(getRandomInterval()) } - }() + } } func (c *Controller) startCloseExpiredPendingTokens(cancelCtx context.Context) { - go func() { - r := rand.New(rand.NewSource(time.Now().UnixNano())) - // desynchronize calls from the controllers, to ease the load on the DB. - getRandomInterval := func() time.Duration { - // 0 to 0.5 adjustment to the base - f := r.Float64() / 2 - // Half a chance to be faster, not slower - if r.Float32() > 0.5 { - f = -1 * f - } - return terminationInterval + time.Duration(f*float64(time.Minute)) + const op = "controller.(Controller).startCloseExpiredPendingTokens" + r := rand.New(rand.NewSource(time.Now().UnixNano())) + // desynchronize calls from the controllers, to ease the load on the DB. + getRandomInterval := func() time.Duration { + // 0 to 0.5 adjustment to the base + f := r.Float64() / 2 + // Half a chance to be faster, not slower + if r.Float32() > 0.5 { + f = -1 * f } - timer := time.NewTimer(0) - for { - select { - case <-cancelCtx.Done(): - c.logger.Info("closing expired pending tokens ticking shutting down") - return + return terminationInterval + time.Duration(f*float64(time.Minute)) + } + timer := time.NewTimer(0) + for { + select { + case <-cancelCtx.Done(): + event.WriteSysEvent(cancelCtx, op, "closing expired pending tokens ticking shutting down") + return - case <-timer.C: - repo, err := c.AuthTokenRepoFn() + case <-timer.C: + repo, err := c.AuthTokenRepoFn() + if err != nil { + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error fetching repository for closing expired pending tokens")) + } else { + closeCount, err := repo.CloseExpiredPendingTokens(cancelCtx) if err != nil { - c.logger.Error("error fetching repository for closing expired pending tokens", "error", err) - } else { - closeCount, err := repo.CloseExpiredPendingTokens(cancelCtx) - if err != nil { - c.logger.Error("error performing closing expired pending tokens", "error", err) - } else if closeCount > 0 { - c.logger.Info("closing expired pending tokens completed sessions successful", "pending_tokens_closed", closeCount) - } + event.WriteError(cancelCtx, op, err, event.WithInfoMsg("error performing closing expired pending tokens")) + } else if closeCount > 0 { + event.WriteSysEvent(cancelCtx, op, "closing expired pending tokens completed sessions successful", "pending_tokens_closed", closeCount) } - timer.Reset(getRandomInterval()) } + timer.Reset(getRandomInterval()) } - }() + } } diff --git a/internal/servers/worker/controller_connection.go b/internal/servers/worker/controller_connection.go index 4fd50940f..ad51977c9 100644 --- a/internal/servers/worker/controller_connection.go +++ b/internal/servers/worker/controller_connection.go @@ -19,6 +19,7 @@ import ( "github.com/hashicorp/boundary/internal/cmd/base" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-secure-stdlib/base62" "google.golang.org/grpc" "google.golang.org/grpc/resolver" @@ -26,6 +27,7 @@ import ( ) func (w *Worker) startControllerConnections() error { + const op = "worker.(Worker).startControllerConnections" initialAddrs := make([]resolver.Address, 0, len(w.conf.RawConfig.Worker.Controllers)) for _, addr := range w.conf.RawConfig.Worker.Controllers { switch { @@ -34,7 +36,6 @@ func (w *Worker) startControllerConnections() error { default: host, port, err := net.SplitHostPort(addr) if err != nil && strings.Contains(err.Error(), "missing port in address") { - w.logger.Trace("missing port in controller address, using port 9201", "address", addr) host, port, err = net.SplitHostPort(net.JoinHostPort(addr, "9201")) } if err != nil { @@ -59,6 +60,7 @@ func (w *Worker) startControllerConnections() error { } func (w Worker) controllerDialerFunc() func(context.Context, string) (net.Conn, error) { + const op = "worker.(Worker).controllerDialerFunc" return func(ctx context.Context, addr string) (net.Conn, error) { tlsConf, authInfo, err := w.workerAuthTLSConfig() if err != nil { @@ -79,13 +81,13 @@ func (w Worker) controllerDialerFunc() func(context.Context, string) (net.Conn, written, err := tlsConn.Write([]byte(authInfo.ConnectionNonce)) if err != nil { if err := nonTlsConn.Close(); err != nil { - w.logger.Error("error closing connection after writing failure", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing connection after writing failure")) } return nil, fmt.Errorf("unable to write connection nonce: %w", err) } if written != len(authInfo.ConnectionNonce) { if err := nonTlsConn.Close(); err != nil { - w.logger.Error("error closing connection after writing failure", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error closing connection after writing failure")) } return nil, fmt.Errorf("expected to write %d bytes of connection nonce, wrote %d", len(authInfo.ConnectionNonce), written) } @@ -94,6 +96,7 @@ func (w Worker) controllerDialerFunc() func(context.Context, string) (net.Conn, } func (w *Worker) createClientConn(addr string) error { + const op = "worker.(Worker)createClientConn" defaultTimeout := (time.Second + time.Nanosecond).String() defServiceConfig := fmt.Sprintf(` { @@ -127,7 +130,7 @@ func (w *Worker) createClientConn(addr string) error { w.controllerStatusConn.Store(pbs.NewServerCoordinationServiceClient(cc)) w.controllerSessionConn.Store(pbs.NewSessionServiceClient(cc)) - w.logger.Info("connected to controller", "address", addr) + event.WriteSysEvent(context.TODO(), op, "connected to controller", "address", addr) return nil } diff --git a/internal/servers/worker/handler.go b/internal/servers/worker/handler.go index 77c0b93f9..91b610985 100644 --- a/internal/servers/worker/handler.go +++ b/internal/servers/worker/handler.go @@ -2,12 +2,14 @@ package worker import ( "context" + "errors" "net" "net/http" "strconv" "github.com/hashicorp/boundary/globals" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/proxy" "github.com/hashicorp/go-secure-stdlib/listenerutil" "nhooyr.io/websocket" @@ -32,9 +34,11 @@ func (w *Worker) handler(props HandlerProperties) http.Handler { } func (w *Worker) handleProxy() http.HandlerFunc { + const op = "worker.(Worker).handleProxy" return http.HandlerFunc(func(wr http.ResponseWriter, r *http.Request) { + ctx := r.Context() if r.TLS == nil { - w.logger.Error("no request TLS information found") + event.WriteError(ctx, op, errors.New("no request TLS information found")) wr.WriteHeader(http.StatusInternalServerError) return } @@ -42,13 +46,13 @@ func (w *Worker) handleProxy() http.HandlerFunc { clientIp, clientPort, err := net.SplitHostPort(r.RemoteAddr) if err != nil { - w.logger.Error("unable to understand remote address", "error", err, "remote_addr", r.RemoteAddr) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to understand remote address", "remote_addr", r.RemoteAddr)) wr.WriteHeader(http.StatusInternalServerError) return } numPort, err := strconv.Atoi(clientPort) if err != nil { - w.logger.Error("unable to understand remote port", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to understand remote port")) wr.WriteHeader(http.StatusInternalServerError) return } @@ -57,11 +61,11 @@ func (w *Worker) handleProxy() http.HandlerFunc { Port: numPort, } - w.logger.Trace("received TLS connection") + event.WriteSysEvent(ctx, op, "received TLS connection") siRaw, valid := w.sessionInfoMap.Load(sessionId) if !valid { - w.logger.Error("session not found in info map", "session_id", sessionId) + event.WriteError(ctx, op, errors.New("session not found in info map"), event.WithInfo("session_id", sessionId)) wr.WriteHeader(http.StatusInternalServerError) return } @@ -75,56 +79,56 @@ func (w *Worker) handleProxy() http.HandlerFunc { sessStatus := si.status si.RUnlock() - w.logger.Trace("found session in session info map") + event.WriteSysEvent(ctx, op, "found session in session info map") opts := &websocket.AcceptOptions{ Subprotocols: []string{globals.TcpProxyV1}, } conn, err := websocket.Accept(wr, r, opts) if err != nil { - w.logger.Error("error during websocket upgrade", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error during websocket upgrade")) wr.WriteHeader(http.StatusInternalServerError) return } // Later calls will cause this to noop if they return a different status defer conn.Close(websocket.StatusNormalClosure, "done") - w.logger.Trace("websocket upgrade done") + event.WriteSysEvent(ctx, op, "websocket upgrade done") connCtx, connCancel := context.WithDeadline(r.Context(), expiration.AsTime()) defer connCancel() var handshake proxy.ClientHandshake if err := wspb.Read(connCtx, conn, &handshake); err != nil { - w.logger.Error("error reading handshake from client", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error reading handshake from client")) conn.Close(websocket.StatusPolicyViolation, "invalid handshake received") return } if len(handshake.GetTofuToken()) < 20 { - w.logger.Error("invalid tofu token") + event.WriteError(ctx, op, errors.New("invalid tofu token")) conn.Close(websocket.StatusUnsupportedData, "invalid tofu token") return } - w.logger.Trace("proxy handshake finished") + event.WriteSysEvent(ctx, op, "proxy handshake finished") if tofuToken != "" { if tofuToken != handshake.GetTofuToken() { - w.logger.Error("WARNING: mismatched tofu token", "session_id", sessionId) + event.WriteError(ctx, op, errors.New("WARNING: mismatched tofu token"), event.WithInfo("session_id", sessionId)) conn.Close(websocket.StatusPolicyViolation, "tofu token not allowed") return } } else { if sessStatus != pbs.SESSIONSTATUS_SESSIONSTATUS_PENDING { - w.logger.Error("no tofu token but not in correct session state", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("no tofu token but not in correct session state")) conn.Close(websocket.StatusInternalError, "refusing to activate session") return } if handshake.Command == proxy.HANDSHAKECOMMAND_HANDSHAKECOMMAND_UNSPECIFIED { - w.logger.Trace("activating session") + event.WriteSysEvent(ctx, op, "activating session") sessStatus, err = w.activateSession(r.Context(), sessionId, handshake.GetTofuToken(), version) if err != nil { - w.logger.Error("unable to validate session", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to validate session")) conn.Close(websocket.StatusInternalError, "unable to activate session") return } @@ -132,10 +136,10 @@ func (w *Worker) handleProxy() http.HandlerFunc { } if handshake.Command == proxy.HANDSHAKECOMMAND_HANDSHAKECOMMAND_SESSION_CANCEL { - w.logger.Trace("canceling session at client request") + event.WriteSysEvent(ctx, op, "canceling session at client request") _, err := w.cancelSession(r.Context(), sessionId) if err != nil { - w.logger.Error("unable to cancel session", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to cancel session")) conn.Close(websocket.StatusInternalError, "unable to cancel session") return } @@ -147,7 +151,7 @@ func (w *Worker) handleProxy() http.HandlerFunc { var connsLeft int32 ci, connsLeft, err = w.authorizeConnection(r.Context(), sessionId) if err != nil { - w.logger.Error("unable to authorize connection", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("unable to authorize connection")) conn.Close(websocket.StatusInternalError, "unable to authorize connection") return } @@ -164,7 +168,7 @@ func (w *Worker) handleProxy() http.HandlerFunc { connectionLimit := si.lookupSessionResponse.GetConnectionLimit() si.Unlock() - w.logger.Trace("authorized connection", "connection_id", ci.id) + event.WriteSysEvent(ctx, op, "authorized connection", "connection_id", ci.id) handshakeResult := &proxy.HandshakeResult{ Expiration: expiration, @@ -172,7 +176,7 @@ func (w *Worker) handleProxy() http.HandlerFunc { ConnectionsLeft: connsLeft, } if err := wspb.Write(connCtx, conn, handshakeResult); err != nil { - w.logger.Error("error sending handshake result to client", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error sending handshake result to client")) conn.Close(websocket.StatusProtocolError, "unable to send handshake result") return } diff --git a/internal/servers/worker/session.go b/internal/servers/worker/session.go index 87fd14755..a2b3e63e7 100644 --- a/internal/servers/worker/session.go +++ b/internal/servers/worker/session.go @@ -12,6 +12,7 @@ import ( "time" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/session" ) @@ -37,35 +38,37 @@ type sessionInfo struct { } func (w *Worker) getSessionTls(hello *tls.ClientHelloInfo) (*tls.Config, error) { + const op = "worker.(Worker).getSessionTls" + ctx := context.TODO() var sessionId string switch { case strings.HasPrefix(hello.ServerName, "s_"): - w.logger.Trace("got valid session in SNI", "session_id", hello.ServerName) + event.WriteSysEvent(ctx, op, "got valid session in SNI", "session_id", hello.ServerName) sessionId = hello.ServerName default: - w.logger.Trace("invalid session in SNI", "session_id", hello.ServerName) + event.WriteSysEvent(ctx, op, "invalid session in SNI", "session_id", hello.ServerName) return nil, fmt.Errorf("could not find session ID in SNI") } rawConn := w.controllerSessionConn.Load() if rawConn == nil { - w.logger.Trace("could not get a controller client", "session_id", sessionId) + event.WriteSysEvent(ctx, op, "could not get a controller client", "session_id", sessionId) return nil, errors.New("could not get a controller client") } conn, ok := rawConn.(pbs.SessionServiceClient) if !ok { - w.logger.Trace("could not cast controller client to the real thing", "session_id", sessionId) + event.WriteSysEvent(ctx, op, "could not cast controller client to the real thing", "session_id", sessionId) return nil, errors.New("could not cast atomic controller client to the real thing") } if conn == nil { - w.logger.Trace("controller client is nil", "session_id", sessionId) + event.WriteSysEvent(ctx, op, "controller client is nil", "session_id", sessionId) return nil, errors.New("controller client is nil") } timeoutContext, cancel := context.WithTimeout(w.baseContext, validateSessionTimeout) defer cancel() - w.logger.Trace("looking up session", "session_id", sessionId) + event.WriteSysEvent(ctx, op, "looking up session", "session_id", sessionId) resp, err := conn.LookupSession(timeoutContext, &pbs.LookupSessionRequest{ ServerId: w.conf.RawConfig.Worker.Name, SessionId: sessionId, @@ -124,7 +127,7 @@ func (w *Worker) getSessionTls(hello *tls.ClientHelloInfo) (*tls.Config, error) actualSi.Unlock() } - w.logger.Trace("returning TLS configuration", "session_id", sessionId) + event.WriteSysEvent(ctx, op, "returning TLS configuration", "session_id", sessionId) return tlsConf, nil } @@ -228,6 +231,7 @@ func (w *Worker) connectConnection(ctx context.Context, req *pbs.ConnectConnecti } func (w *Worker) closeConnection(ctx context.Context, req *pbs.CloseConnectionRequest) (*pbs.CloseConnectionResponse, error) { + const op = "worker.(Worker).closeConnections" rawConn := w.controllerSessionConn.Load() if rawConn == nil { return nil, errors.New("could not get a controller client") @@ -245,7 +249,7 @@ func (w *Worker) closeConnection(ctx context.Context, req *pbs.CloseConnectionRe return nil, err } if len(resp.GetCloseResponseData()) != len(req.GetCloseRequestData()) { - w.logger.Warn("mismatched number of states returned on connection closed", "expected", len(req.GetCloseRequestData()), "got", len(resp.GetCloseResponseData())) + event.WriteError(ctx, op, errors.New("mismatched number of states returned on connection closed"), event.WithInfo("expected", len(req.GetCloseRequestData()), "got", len(resp.GetCloseResponseData()))) } return resp, nil @@ -259,13 +263,14 @@ func (w *Worker) closeConnection(ctx context.Context, req *pbs.CloseConnectionRe // closeInfo is a map of connections mapped to their individual // session. func (w *Worker) closeConnections(ctx context.Context, closeInfo map[string]string) { + const op = "worker.(Worker).closeConnections" if closeInfo == nil { // This should not happen, but it's a no-op if it does. Just // return. return } - w.logger.Trace("marking connections as closed", "session_and_connection_ids", fmt.Sprintf("%#v", closeInfo)) + event.WriteSysEvent(ctx, op, "marking connections as closed", "session_and_connection_ids", fmt.Sprintf("%#v", closeInfo)) // How we handle close info depends on whether or not we succeeded with // marking them closed on the controller. @@ -280,11 +285,10 @@ func (w *Worker) closeConnections(ctx context.Context, closeInfo map[string]stri defer closeConnCancel() response, err := w.closeConnection(closeConnCtx, w.makeCloseConnectionRequest(closeInfo)) if err != nil { - w.logger.Error("error marking connections closed", "error", err) - w.logger.Warn( - "error contacting controller, connections will be closed only on worker", + event.WriteError(ctx, op, err, event.WithInfoMsg("error marking connections closed", + "warning", "error contacting controller, connections will be closed only on worker", "session_and_connection_ids", fmt.Sprintf("%#v", closeInfo), - ) + )) // Since we could not reach the controller, we have to make a "fake" response set. sessionCloseInfo, err = w.makeFakeSessionCloseInfo(closeInfo) @@ -295,8 +299,7 @@ func (w *Worker) closeConnections(ctx context.Context, closeInfo map[string]stri } if err != nil { - w.logger.Error(err.Error()) - w.logger.Error("serious error in processing return data from controller, aborting additional session/connection state modification") + event.WriteError(ctx, op, err, event.WithInfoMsg("serious error in processing return data from controller, aborting additional session/connection state modification")) return } @@ -304,11 +307,11 @@ func (w *Worker) closeConnections(ctx context.Context, closeInfo map[string]stri closedIds, errs := w.setCloseTimeForResponse(sessionCloseInfo) if len(errs) > 0 { for _, err := range errs { - w.logger.Error("error marking connection closed in state", "err", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error marking connection closed in state")) } } - w.logger.Trace("connections successfully marked closed", "connection_ids", closedIds) + event.WriteSysEvent(ctx, op, "connections successfully marked closed", "connection_ids", closedIds) } // makeCloseConnectionRequest creates a CloseConnectionRequest for diff --git a/internal/servers/worker/status.go b/internal/servers/worker/status.go index 91d34e51e..5ab1a77a0 100644 --- a/internal/servers/worker/status.go +++ b/internal/servers/worker/status.go @@ -2,10 +2,12 @@ package worker import ( "context" + "errors" "math/rand" "time" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers" "github.com/hashicorp/boundary/internal/types/resource" "google.golang.org/grpc/resolver" @@ -23,34 +25,33 @@ type LastStatusInformation struct { } func (w *Worker) startStatusTicking(cancelCtx context.Context) { - go func() { - r := rand.New(rand.NewSource(time.Now().UnixNano())) - // This function exists to desynchronize calls to controllers from - // workers so we aren't always getting status updates at the exact same - // intervals, to ease the load on the DB. - getRandomInterval := func() time.Duration { - // 0 to 0.5 adjustment to the base - f := r.Float64() / 2 - // Half a chance to be faster, not slower - if r.Float32() > 0.5 { - f = -1 * f - } - return statusInterval + time.Duration(f*float64(time.Second)) + const op = "worker.(Worker).startStatusTicking" + r := rand.New(rand.NewSource(time.Now().UnixNano())) + // This function exists to desynchronize calls to controllers from + // workers so we aren't always getting status updates at the exact same + // intervals, to ease the load on the DB. + getRandomInterval := func() time.Duration { + // 0 to 0.5 adjustment to the base + f := r.Float64() / 2 + // Half a chance to be faster, not slower + if r.Float32() > 0.5 { + f = -1 * f } + return statusInterval + time.Duration(f*float64(time.Second)) + } - timer := time.NewTimer(0) - for { - select { - case <-cancelCtx.Done(): - w.logger.Info("status ticking shutting down") - return + timer := time.NewTimer(0) + for { + select { + case <-cancelCtx.Done(): + event.WriteSysEvent(context.TODO(), op, "status ticking shutting down") + return - case <-timer.C: - w.sendWorkerStatus(cancelCtx) - timer.Reset(getRandomInterval()) - } + case <-timer.C: + w.sendWorkerStatus(cancelCtx) + timer.Reset(getRandomInterval()) } - }() + } } // LastStatusSuccess reports the last time we sent a successful @@ -67,17 +68,18 @@ func (w *Worker) LastStatusSuccess() *LastStatusInformation { // The timeout is aligned with the worker's status grace period. A nil error // means the status was sent successfully. func (w *Worker) WaitForNextSuccessfulStatusUpdate() error { - w.logger.Debug("waiting for next status report to controller") + const op = "worker.(Worker).WaitForNextSuccessfulStatusUpdate" waitStatusStart := time.Now() ctx, cancel := context.WithTimeout(w.baseContext, w.conf.StatusGracePeriodDuration) defer cancel() + event.WriteSysEvent(ctx, op, "waiting for next status report to controller") for { select { case <-time.After(time.Second): // pass case <-ctx.Done(): - w.logger.Error("error waiting for next status report to controller", "err", ctx.Err()) + event.WriteError(ctx, op, ctx.Err(), event.WithInfoMsg("error waiting for next status report to controller")) return ctx.Err() } @@ -86,11 +88,12 @@ func (w *Worker) WaitForNextSuccessfulStatusUpdate() error { } } - w.logger.Debug("next worker status update sent successfully") + event.WriteSysEvent(ctx, op, "next worker status update sent successfully") return nil } func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { + const op = "worker.(Worker).sendWorkerStatus" // First send info as-is. We'll perform cleanup duties after we // get cancel/job change info back. var activeJobs []*pbs.JobStatus @@ -148,7 +151,7 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { UpdateTags: w.updateTags.Load(), }) if err != nil { - w.logger.Error("error making status request to controller", "error", err) + event.WriteError(statusCtx, op, err, event.WithInfoMsg("error making status request to controller")) // Check for last successful status. Ignore nil last status, this probably // means that we've never connected to a controller, and as such probably // don't have any sessions to worry about anyway. @@ -159,9 +162,9 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { // connections should continue to exist. if isPastGrace, lastStatusTime, gracePeriod := w.isPastGrace(); isPastGrace { - w.logger.Warn("status error grace period has expired, canceling all sessions on worker", - "last_status_time", lastStatusTime.String(), - "grace_period", gracePeriod, + event.WriteError(statusCtx, op, + errors.New("status error grace period has expired, canceling all sessions on worker"), + event.WithInfo("last_status_time", lastStatusTime.String(), "grace_period", gracePeriod), ) // Run a "cleanup" for all sessions that will not be caught by @@ -169,7 +172,6 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { w.cleanupConnections(cancelCtx, true) } } else { - w.logger.Trace("successfully sent status to controller") w.updateTags.Store(false) addrs := make([]resolver.Address, 0, len(result.Controllers)) strAddrs := make([]string, 0, len(result.Controllers)) @@ -177,17 +179,16 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { addrs = append(addrs, resolver.Address{Addr: v.Address}) strAddrs = append(strAddrs, v.Address) } - w.logger.Trace("found controllers", "addresses", strAddrs) switch len(strAddrs) { case 0: - w.logger.Warn("got no controller addresses from controller; possibly prior to first status save, not persisting") + event.WriteError(statusCtx, op, errors.New("got no controller addresses from controller; possibly prior to first status save, not persisting")) default: w.Resolver().UpdateState(resolver.State{Addresses: addrs}) } w.lastStatusSuccess.Store(&LastStatusInformation{StatusResponse: result, StatusTime: time.Now()}) for _, request := range result.GetJobsRequests() { - w.logger.Trace("got job request from controller", "request", request) + event.WriteSysEvent(statusCtx, op, "got job request from controller", "request", request) switch request.GetRequestType() { case pbs.CHANGETYPE_CHANGETYPE_UPDATE_STATE: switch request.GetJob().GetType() { @@ -196,7 +197,7 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { sessionId := sessInfo.GetSessionId() siRaw, ok := w.sessionInfoMap.Load(sessionId) if !ok { - w.logger.Warn("session change requested but could not find local information for it", "session_id", sessionId) + event.WriteError(statusCtx, op, errors.New("session change requested but could not find local information for it"), event.WithInfo("session_id", sessionId)) continue } si := siRaw.(*sessionInfo) @@ -208,7 +209,7 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { connId := conn.GetConnectionId() connInfo, ok := si.connInfoMap[connId] if !ok { - w.logger.Warn("connection change requested but could not find local information for it", "connection_id", connId) + event.WriteError(statusCtx, op, errors.New("connection change requested but could not find local information for it"), event.WithInfo("connection_id", connId)) continue } @@ -234,6 +235,7 @@ func (w *Worker) sendWorkerStatus(cancelCtx context.Context) { // connections, regardless of whether or not the session is still // active. func (w *Worker) cleanupConnections(cancelCtx context.Context, ignoreSessionState bool) { + const op = "worker.(Worker).cleanupConnections" closeInfo := make(map[string]string) cleanSessionIds := make([]string, 0) w.sessionInfoMap.Range(func(key, value interface{}) bool { @@ -250,7 +252,7 @@ func (w *Worker) cleanupConnections(cancelCtx context.Context, ignoreSessionStat closedIds := w.cancelConnections(si.connInfoMap, true) for _, connId := range closedIds { closeInfo[connId] = si.id - w.logger.Info("terminated connection due to cancellation or expiration", "session_id", si.id, "connection_id", connId) + event.WriteSysEvent(cancelCtx, op, "terminated connection due to cancellation or expiration", "session_id", si.id, "connection_id", connId) } // closeTime is marked by closeConnections iff the @@ -268,7 +270,7 @@ func (w *Worker) cleanupConnections(cancelCtx context.Context, ignoreSessionStat closedIds := w.cancelConnections(si.connInfoMap, false) for _, connId := range closedIds { closeInfo[connId] = si.id - w.logger.Info("terminated connection due to cancellation or expiration", "session_id", si.id, "connection_id", connId) + event.WriteSysEvent(cancelCtx, op, "terminated connection due to cancellation or expiration", "session_id", si.id, "connection_id", connId) } } diff --git a/internal/servers/worker/status_test.go b/internal/servers/worker/status_test.go index e88082b7e..b49d156c9 100644 --- a/internal/servers/worker/status_test.go +++ b/internal/servers/worker/status_test.go @@ -8,12 +8,21 @@ import ( "time" "github.com/hashicorp/boundary/internal/cmd/base" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/require" ) func TestWorkerWaitForNextSuccessfulStatusUpdate(t *testing.T) { - t.Parallel() + // do not runn using t.Parallel() since it relies on the sys eventer + event.TestEnableEventing(t, true) + testConfig := event.DefaultEventerConfig() + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + }) + err := event.InitSysEventer(testLogger, testLock, "TestWorkerWaitForNextSuccessfulStatusUpdate", event.WithEventerConfig(testConfig)) + require.NoError(t, err) for _, name := range []string{"ok", "timeout"} { t.Run(name, func(t *testing.T) { require := require.New(t) diff --git a/internal/servers/worker/tcp_proxy.go b/internal/servers/worker/tcp_proxy.go index 8ff1510d8..66b210464 100644 --- a/internal/servers/worker/tcp_proxy.go +++ b/internal/servers/worker/tcp_proxy.go @@ -10,27 +10,30 @@ import ( "nhooyr.io/websocket" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" ) func (w *Worker) handleTcpProxyV1(connCtx context.Context, clientAddr *net.TCPAddr, conn *websocket.Conn, si *sessionInfo, connectionId, endpoint string) { + const op = "worker.(Worker).handleTcpProxyV1" + ctx := context.TODO() si.RLock() sessionId := si.lookupSessionResponse.GetAuthorization().GetSessionId() si.RUnlock() sessionUrl, err := url.Parse(endpoint) if err != nil { - w.logger.Error("error parsing endpoint information", "error", err, "session_id", sessionId, "endpoint", endpoint) + event.WriteError(ctx, op, err, event.WithInfoMsg("error parsing endpoint information", "session_id", sessionId, "endpoint", endpoint)) conn.Close(websocket.StatusInternalError, "cannot parse endpoint url") return } if sessionUrl.Scheme != "tcp" { - w.logger.Error("invalid scheme for tcp proxy", "error", err, "session_id", sessionId, "endpoint", endpoint) + event.WriteError(ctx, op, err, event.WithInfo("session_id", sessionId, "endpoint", endpoint)) conn.Close(websocket.StatusInternalError, "invalid scheme for type") return } remoteConn, err := net.Dial("tcp", sessionUrl.Host) if err != nil { - w.logger.Error("error dialing endpoint", "error", err, "endpoint", endpoint) + event.WriteError(ctx, op, err, event.WithInfoMsg("error dialing endpoint", "endpoint", endpoint)) conn.Close(websocket.StatusInternalError, "endpoint dialing failed") return } @@ -49,7 +52,7 @@ func (w *Worker) handleTcpProxyV1(connCtx context.Context, clientAddr *net.TCPAd connStatus, err := w.connectConnection(connCtx, connectionInfo) if err != nil { - w.logger.Error("error marking connection as connected", "error", err) + event.WriteError(ctx, op, err, event.WithInfoMsg("error marking connection as connected")) conn.Close(websocket.StatusInternalError, "failed to mark connection as connected") return } @@ -67,14 +70,14 @@ func (w *Worker) handleTcpProxyV1(connCtx context.Context, clientAddr *net.TCPAd _, err := io.Copy(netConn, tcpRemoteConn) netConn.Close() tcpRemoteConn.Close() - w.logger.Debug("copy from client to endpoint done", "error", err) + event.WriteSysEvent(ctx, op, "copy from client to endpoint done", "error", err) }() go func() { defer connWg.Done() _, err := io.Copy(tcpRemoteConn, netConn) tcpRemoteConn.Close() netConn.Close() - w.logger.Debug("copy from endpoint to client done", "error", err) + event.WriteSysEvent(ctx, op, "copy from endpoint to client done", "error", err) }() connWg.Wait() } diff --git a/internal/servers/worker/testing.go b/internal/servers/worker/testing.go index 6801b5c40..44025ed9b 100644 --- a/internal/servers/worker/testing.go +++ b/internal/servers/worker/testing.go @@ -10,6 +10,7 @@ import ( "github.com/hashicorp/boundary/internal/cmd/base" "github.com/hashicorp/boundary/internal/cmd/config" pbs "github.com/hashicorp/boundary/internal/gen/controller/servers/services" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-hclog" wrapping "github.com/hashicorp/go-kms-wrapping" "github.com/hashicorp/go-secure-stdlib/base62" @@ -183,6 +184,7 @@ type TestWorkerOpts struct { } func NewTestWorker(t *testing.T, opts *TestWorkerOpts) *TestWorker { + const op = "worker.NewTestWorker" ctx, cancel := context.WithCancel(context.Background()) tw := &TestWorker{ @@ -234,7 +236,7 @@ func NewTestWorker(t *testing.T, opts *TestWorkerOpts) *TestWorker { if err != nil { t.Fatal(err) } - tw.b.Logger.Info("worker name generated", "name", opts.Config.Worker.Name) + event.WriteSysEvent(ctx, op, "worker name generated", "name", opts.Config.Worker.Name) } tw.name = opts.Config.Worker.Name @@ -285,6 +287,7 @@ func NewTestWorker(t *testing.T, opts *TestWorkerOpts) *TestWorker { } func (tw *TestWorker) AddClusterWorkerMember(t *testing.T, opts *TestWorkerOpts) *TestWorker { + const op = "worker.(TestWorker).AddClusterWorkerMember" if opts == nil { opts = new(TestWorkerOpts) } @@ -295,16 +298,13 @@ func (tw *TestWorker) AddClusterWorkerMember(t *testing.T, opts *TestWorkerOpts) Logger: tw.w.conf.Logger, StatusGracePeriodDuration: opts.StatusGracePeriodDuration, } - if opts.Logger != nil { - nextOpts.Logger = opts.Logger - } if nextOpts.Name == "" { var err error nextOpts.Name, err = base62.Random(5) if err != nil { t.Fatal(err) } - nextOpts.Logger.Info("worker name generated", "name", nextOpts.Name) + event.WriteSysEvent(context.TODO(), op, "worker name generated", "name", nextOpts.Name) } return NewTestWorker(t, nextOpts) } diff --git a/internal/servers/worker/worker.go b/internal/servers/worker/worker.go index d4684f10a..57e23ae5d 100644 --- a/internal/servers/worker/worker.go +++ b/internal/servers/worker/worker.go @@ -10,6 +10,7 @@ import ( "time" "github.com/hashicorp/boundary/internal/cmd/config" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/servers" "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/mlock" @@ -26,6 +27,8 @@ type Worker struct { baseCancel context.CancelFunc started *ua.Bool + tickerWg sync.WaitGroup + controllerStatusConn *atomic.Value lastStatusSuccess *atomic.Value workerStartTime time.Time @@ -95,8 +98,9 @@ func New(conf *Config) (*Worker, error) { } func (w *Worker) Start() error { + const op = "worker.(Worker).Start" if w.started.Load() { - w.logger.Info("already started, skipping") + event.WriteSysEvent(context.TODO(), op, "already started, skipping") return nil } @@ -113,7 +117,12 @@ func (w *Worker) Start() error { return fmt.Errorf("error making controller connections: %w", err) } - w.startStatusTicking(w.baseContext) + w.tickerWg.Add(1) + go func() { + defer w.tickerWg.Done() + w.startStatusTicking(w.baseContext) + }() + w.workerStartTime = time.Now() w.started.Store(true) @@ -125,10 +134,12 @@ func (w *Worker) Start() error { // to create new listeners we'd have to migrate listener setup logic here -- // doable, but work for later. func (w *Worker) Shutdown(skipListeners bool) error { + const op = "worker.(Worker).Shutdown" if !w.started.Load() { - w.logger.Info("already shut down, skipping") + event.WriteSysEvent(context.TODO(), op, "already shut down, skipping") return nil } + defer w.started.Store(false) w.Resolver().UpdateState(resolver.State{Addresses: []resolver.Address{}}) w.baseCancel() if !skipListeners { @@ -136,7 +147,7 @@ func (w *Worker) Shutdown(skipListeners bool) error { return fmt.Errorf("error stopping worker listeners: %w", err) } } - w.started.Store(false) + w.tickerWg.Wait() if w.conf.Eventer != nil { if err := w.conf.Eventer.FlushNodes(context.Background()); err != nil { return fmt.Errorf("error flushing worker eventer nodes: %w", err) diff --git a/internal/tests/cluster/session_cleanup_test.go b/internal/tests/cluster/session_cleanup_test.go index 0b5c84650..d2caed451 100644 --- a/internal/tests/cluster/session_cleanup_test.go +++ b/internal/tests/cluster/session_cleanup_test.go @@ -20,6 +20,7 @@ import ( "github.com/hashicorp/boundary/globals" "github.com/hashicorp/boundary/internal/cmd/config" targetspb "github.com/hashicorp/boundary/internal/gen/controller/api/resources/targets" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/boundary/internal/proxy" "github.com/hashicorp/boundary/internal/servers/controller" "github.com/hashicorp/boundary/internal/servers/worker" @@ -119,6 +120,7 @@ func TestSessionCleanup(t *testing.T) { } func testWorkerSessionCleanupSingle(burdenCase timeoutBurdenType) func(t *testing.T) { + const op = "cluster.testWorkerSessionCleanupSingle" return func(t *testing.T) { t.Parallel() require := require.New(t) @@ -194,11 +196,11 @@ func testWorkerSessionCleanupSingle(burdenCase timeoutBurdenType) func(t *testin sConn := sess.Connect(ctx, t) // Run initial send/receive test, make sure things are working - logger.Debug("running initial send/recv test") + event.WriteSysEvent(ctx, op, "running initial send/recv test") sConn.TestSendRecvAll(t) // Kill the link - logger.Debug("pausing controller/worker link") + event.WriteSysEvent(ctx, op, "pausing controller/worker link") proxy.Pause() // Wait for failure connection state (depends on burden case) @@ -232,7 +234,7 @@ func testWorkerSessionCleanupSingle(burdenCase timeoutBurdenType) func(t *testin } // Resume the connection, and reconnect. - logger.Debug("resuming controller/worker link") + event.WriteSysEvent(ctx, op, "resuming controller/worker link") proxy.Resume() err = w1.Worker().WaitForNextSuccessfulStatusUpdate() require.NoError(err) @@ -257,7 +259,7 @@ func testWorkerSessionCleanupSingle(burdenCase timeoutBurdenType) func(t *testin } // Proceed with new connection test - logger.Debug("connecting to new session after resuming controller/worker link") + event.WriteSysEvent(ctx, op, "connecting to new session after resuming controller/worker link") sess = newTestSession(ctx, t, logger, tcl, "ttcp_1234567890") // re-assign, other connection will close in t.Cleanup() sConn = sess.Connect(ctx, t) sConn.TestSendRecvAll(t) @@ -265,6 +267,7 @@ func testWorkerSessionCleanupSingle(burdenCase timeoutBurdenType) func(t *testin } func testWorkerSessionCleanupMulti(burdenCase timeoutBurdenType) func(t *testing.T) { + const op = "cluster.testWorkerSessionCleanupMulti" return func(t *testing.T) { t.Parallel() require := require.New(t) @@ -376,20 +379,20 @@ func testWorkerSessionCleanupMulti(burdenCase timeoutBurdenType) func(t *testing sConn := sess.Connect(ctx, t) // Run initial send/receive test, make sure things are working - logger.Debug("running initial send/recv test") + event.WriteSysEvent(ctx, op, "running initial send/recv test") sConn.TestSendRecvAll(t) // Kill connection to first controller, and run test again, should // pass, deferring to other controller. Wait for the next // successful status report to ensure this. - logger.Debug("pausing link to controller #1") + event.WriteSysEvent(ctx, op, "pausing link to controller #1") p1.Pause() err = w1.Worker().WaitForNextSuccessfulStatusUpdate() require.NoError(err) sConn.TestSendRecvAll(t) // Resume first controller, pause second. This one should work too. - logger.Debug("pausing link to controller #2, resuming #1") + event.WriteSysEvent(ctx, op, "pausing link to controller #2, resuming #1") p1.Resume() p2.Pause() err = w1.Worker().WaitForNextSuccessfulStatusUpdate() @@ -398,7 +401,7 @@ func testWorkerSessionCleanupMulti(burdenCase timeoutBurdenType) func(t *testing // Kill the first controller connection again. This one should fail // due to lack of any connection. - logger.Debug("pausing link to controller #1 again, both connections should be offline") + event.WriteSysEvent(ctx, op, "pausing link to controller #1 again, both connections should be offline") p1.Pause() // Wait for failure connection state (depends on burden case) @@ -432,7 +435,7 @@ func testWorkerSessionCleanupMulti(burdenCase timeoutBurdenType) func(t *testing } // Finally resume both, try again. Should behave as per normal. - logger.Debug("resuming connections to both controllers") + event.WriteSysEvent(ctx, op, "resuming connections to both controllers") p1.Resume() p2.Resume() err = w1.Worker().WaitForNextSuccessfulStatusUpdate() @@ -458,7 +461,7 @@ func testWorkerSessionCleanupMulti(burdenCase timeoutBurdenType) func(t *testing } // Proceed with new connection test - logger.Debug("connecting to new session after resuming controller/worker link") + event.WriteSysEvent(ctx, op, "connecting to new session after resuming controller/worker link") sess = newTestSession(ctx, t, logger, tcl, "ttcp_1234567890") // re-assign, other connection will close in t.Cleanup() sConn = sess.Connect(ctx, t) sConn.TestSendRecvAll(t) @@ -587,6 +590,7 @@ func (s *testSession) ExpectConnectionStateOnController( tc *controller.TestController, expectState session.ConnectionStatus, ) { + const op = "cluster.(testSession).ExpectConnectionStateOnController" t.Helper() require := require.New(t) assert := assert.New(t) @@ -645,7 +649,7 @@ func (s *testSession) ExpectConnectionStateOnController( // Assert require.Equal(expectStates, actualStates) - s.logger.Debug("successfully asserted all connection states on controller", "expected_states", expectStates, "actual_states", actualStates) + event.WriteSysEvent(ctx, op, "successfully asserted all connection states on controller", "expected_states", expectStates, "actual_states", actualStates) } // ExpectConnectionStateOnWorker waits until all connections in a @@ -656,6 +660,7 @@ func (s *testSession) ExpectConnectionStateOnWorker( tw *worker.TestWorker, expectState session.ConnectionStatus, ) { + const op = "cluster.(testSession).ExpectConnectionStateOnWorker" t.Helper() require := require.New(t) assert := assert.New(t) @@ -701,7 +706,7 @@ func (s *testSession) ExpectConnectionStateOnWorker( // Assert require.Equal(expectStates, actualStates) - s.logger.Debug("successfully asserted all connection states on worker", "expected_states", expectStates, "actual_states", actualStates) + event.WriteSysEvent(ctx, op, "successfully asserted all connection states on worker", "expected_states", expectStates, "actual_states", actualStates) } func (s *testSession) testWorkerConnectionInfo(t *testing.T, tw *worker.TestWorker) map[string]worker.TestConnectionInfo { @@ -765,6 +770,8 @@ func (s *testSession) Connect( // max. The passed in conn is expected to copy whatever it is // received. func (c *testSessionConnection) testSendRecv(t *testing.T) bool { + const op = "cluster.(testSessionConnection).testSendRecv" + ctx := context.TODO() t.Helper() require := require.New(t) @@ -777,7 +784,7 @@ func (c *testSessionConnection) testSendRecv(t *testing.T) bool { // Shuttle over the sequence number as base64. err := binary.Write(c.conn, binary.LittleEndian, i) if err != nil { - c.logger.Debug("received error during write", "err", err) + event.WriteSysEvent(ctx, op, "received error during write", "err", err) if errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) || errors.Is(err, websocket.CloseError{Code: websocket.StatusPolicyViolation, Reason: "timed out"}) { @@ -791,7 +798,7 @@ func (c *testSessionConnection) testSendRecv(t *testing.T) bool { var j uint32 err = binary.Read(c.conn, binary.LittleEndian, &j) if err != nil { - c.logger.Debug("received error during read", "err", err, "num_successfully_sent", i) + event.WriteSysEvent(ctx, op, "received error during read", "err", err, "num_successfully_sent", i) if errors.Is(err, net.ErrClosed) || errors.Is(err, io.EOF) || errors.Is(err, websocket.CloseError{Code: websocket.StatusPolicyViolation, Reason: "timed out"}) { @@ -807,24 +814,26 @@ func (c *testSessionConnection) testSendRecv(t *testing.T) bool { // time.Sleep(time.Second) } - c.logger.Debug("finished send/recv successfully", "num_successfully_sent", testSendRecvSendMax) + event.WriteSysEvent(ctx, op, "finished send/recv successfully", "num_successfully_sent", testSendRecvSendMax) return true } // TestSendRecvAll asserts that we were able to send/recv all pings // over the test connection. func (c *testSessionConnection) TestSendRecvAll(t *testing.T) { + const op = "cluster.(testSessionConnection).TestSendRecvAll" t.Helper() require.True(t, c.testSendRecv(t)) - c.logger.Debug("successfully asserted send/recv as passing") + event.WriteSysEvent(context.TODO(), op, "successfully asserted send/recv as passing") } // TestSendRecvFail asserts that we were able to send/recv all pings // over the test connection. func (c *testSessionConnection) TestSendRecvFail(t *testing.T) { + const op = "cluster.(testSessionConnection).TestSendRecvFail" t.Helper() require.False(t, c.testSendRecv(t)) - c.logger.Debug("successfully asserted send/recv as failing") + event.WriteSysEvent(context.TODO(), op, "successfully asserted send/recv as failing") } type testTcpServer struct { @@ -863,11 +872,12 @@ func (ts *testTcpServer) Close() { } func (ts *testTcpServer) run() { + const op = "cluster.(testTcpServer).run" for { conn, err := ts.ln.Accept() if err != nil { if !errors.Is(err, net.ErrClosed) { - ts.logger.Error("Accept() error in testTcpServer", "err", err) + event.WriteError(context.TODO(), op, err, event.WithInfoMsg("Accept() error in testTcpServer")) } return diff --git a/internal/types/resource/resource.go b/internal/types/resource/resource.go index ceb989ce7..a801cc404 100644 --- a/internal/types/resource/resource.go +++ b/internal/types/resource/resource.go @@ -1,5 +1,7 @@ package resource +import "encoding/json" + // Type defines the types of resources in the system type Type uint @@ -25,6 +27,10 @@ const ( CredentialLibrary ) +func (r Type) MarshalJSON() ([]byte, error) { + return json.Marshal(r.String()) +} + func (r Type) String() string { return [...]string{ "unknown",