Events: convert from hclog to events (#1409)

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

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
 }

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]))
 		}
 	}
 

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]))
 		}
 	}
 

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++

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
 		}

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

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

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

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), "*")
+}

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

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

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

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

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

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

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

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)

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.

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

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

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)

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

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

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
 	}
 

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)

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)

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

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)
 

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

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
 		}
 	}

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{

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
 }
 

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
 }

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
 }

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

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
 }
 

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
 		}

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

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

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)

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

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

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)

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

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