Have fallback eventing use json format (#2216)

* Have fallback eventing use json format

The server will initialize a logger via InitFallbackLogger(...)
after setting up the server's logging (and honoring the related
cmd flags).  This fallback logger will be used if when no eventer
is initialized.

If no fallback logger is initialized, then a event.defaultLogger() will
be used if no eventer is defined.

Co-authored-by: Jim <jlambert@hashicorp.com>

internal/cmd/base/servers.go

@@ -81,7 +81,6 @@ type Server struct {
 	GatedWriter *gatedwriter.Writer
 	Logger      hclog.Logger
 	CombineLogs bool
-	LogLevel    hclog.Level
 
 	StderrLock *sync.Mutex
 	Eventer    *event.Eventer
@@ -253,6 +252,9 @@ func (b *Server) AddEventerToContext(ctx context.Context) (context.Context, erro
 	return e, nil
 }
 
+// SetupLogging sets up the command's logger. This is mostly historical at this
+// point since we switched to eventing; however, logging is still used as a
+// fallback when events are unable to be sent.
 func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, configLogFormat string) error {
 	b.logOutput = os.Stderr
 	if b.CombineLogs {
@@ -268,12 +270,16 @@ func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, confi
 	b.Logger = hclog.New(&hclog.LoggerOptions{
 		Output: b.GatedWriter,
 		Level:  logLevel,
-		// Note that if logFormat is either unspecified or standard, then
-		// the resulting logger's format will be standard.
-		JSONFormat: logFormat == logging.JSONFormat,
+		// Note that if logFormat is either unspecified or json, then
+		// the resulting logger's format will be json.
+		JSONFormat: logFormat != logging.StandardFormat,
 		Mutex:      b.StderrLock,
 	})
 
+	if err := event.InitFallbackLogger(b.Logger); err != nil {
+		return err
+	}
+
 	// create GRPC logger
 	namedGRPCLogFaker := b.Logger.Named("grpclogfaker")
 	grpclog.SetLogger(&GRPCLogFaker{
@@ -284,8 +290,6 @@ func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, confi
 	b.Info["log level"] = logLevel.String()
 	b.InfoKeys = append(b.InfoKeys, "log level")
 
-	b.LogLevel = logLevel
-
 	// log proxy settings
 	// TODO: It would be good to show this but Vault has, or will soon, address
 	// the fact that this can log users/passwords if they are part of the proxy

internal/cmd/commands/dev/dev.go

@@ -300,7 +300,7 @@ func (c *Command) Flags() *base.FlagSets {
 		Name:       "event-format",
 		Target:     &c.flagEventFormat,
 		Completion: complete.PredictSet("cloudevents-json", "cloudevents-text", "hclog-text", "hclog-json"),
-		Usage:      `Event format. Supported values are "cloudevents-json" and "cloudevents-text".`,
+		Usage:      `Event format. Supported values are "cloudevents-json", "cloudevents-text", "hclog-json", and "hclog-text".`,
 	})
 	f.StringVar(&base.StringVar{
 		Name:       "observation-events",

internal/cmd/commands/server/server.go

@@ -113,7 +113,7 @@ func (c *Command) Flags() *base.FlagSets {
 		Target:     &c.flagLogLevel,
 		EnvVar:     "BOUNDARY_LOG_LEVEL",
 		Completion: complete.PredictSet("trace", "debug", "info", "warn", "err"),
-		Usage: "Log verbosity level. Supported values (in order of more detail to less) are " +
+		Usage: "Log verbosity level, mostly as a fallback for events. Supported values (in order of more detail to less) are " +
 			"\"trace\", \"debug\", \"info\", \"warn\", and \"err\".",
 	})
 
@@ -121,7 +121,7 @@ func (c *Command) Flags() *base.FlagSets {
 		Name:       "log-format",
 		Target:     &c.flagLogFormat,
 		Completion: complete.PredictSet("standard", "json"),
-		Usage:      `Log format. Supported values are "standard" and "json".`,
+		Usage:      `Log format, mostly as a fallback for events. Supported values are "standard" and "json".`,
 	})
 
 	return set

internal/observability/event/context.go

@@ -6,8 +6,6 @@ import (
 	"os"
 	"runtime"
 	"time"
-
-	"github.com/hashicorp/go-hclog"
 )
 
 var ci bool
@@ -136,8 +134,7 @@ func WriteError(ctx context.Context, caller Op, e error, opt ...Option) {
 		eventer = SysEventer()
 		if eventer == nil {
 			if !ci {
-				logger := hclog.New(nil)
-				logger.Error(fmt.Sprintf("%s: no eventer available to write error: %v", op, e))
+				fallbackLogger().Error(fmt.Sprintf("%s: no eventer available to write error: %v", op, e))
 			}
 			return
 		}
@@ -286,8 +283,7 @@ func WriteSysEvent(ctx context.Context, caller Op, msg string, args ...interface
 	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))
+			fallbackLogger().Error(fmt.Sprintf("%s: no eventer available to write sysevent: (%s) %+v", op, caller, info))
 			return
 		}
 	}

internal/observability/event/context_test.go

@@ -156,10 +156,7 @@ func Test_RequestInfoFromContext(t *testing.T) {
 func Test_NewEventerContext(t *testing.T) {
 	testSetup := event.TestEventerConfig(t, "Test_NewEventerContext")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	testEventer, err := event.NewEventer(testLogger, testLock, "Test_NewEventerContext", testSetup.EventerConfig)
 	require.NoError(t, err)
 	tests := []struct {
@@ -213,10 +210,7 @@ func Test_EventerFromContext(t *testing.T) {
 	testSetup := event.TestEventerConfig(t, "Test_EventerFromContext")
 
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	testEventer, err := event.NewEventer(testLogger, testLock, "Test_EventerFromContext", testSetup.EventerConfig)
 	require.NoError(t, err)
 
@@ -267,10 +261,7 @@ func Test_WriteObservation(t *testing.T) {
 	c := event.TestEventerConfig(t, "WriteObservation")
 
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	e, err := event.NewEventer(testLogger, testLock, "Test_WriteObservation", c.EventerConfig)
 	require.NoError(t, err)
 
@@ -479,10 +470,6 @@ func Test_WriteObservation(t *testing.T) {
 		c := event.TestEventerConfig(t, "WriteObservation")
 		c.EventerConfig.ObservationsEnabled = false
 		testLock := &sync.Mutex{}
-		testLogger := hclog.New(&hclog.LoggerOptions{
-			Mutex: testLock,
-			Name:  "test",
-		})
 		e, err := event.NewEventer(testLogger, testLock, "not-enabled", c.EventerConfig)
 		require.NoError(err)
 
@@ -504,10 +491,7 @@ func Test_WriteObservation(t *testing.T) {
 
 func Test_Filtering(t *testing.T) {
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	tests := []struct {
 		name  string
 		allow []string
@@ -634,10 +618,7 @@ func Test_WriteAudit(t *testing.T) {
 
 	c := event.TestEventerConfig(t, "WriteAudit")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	e, err := event.NewEventer(testLogger, testLock, "Test_WriteAudit", c.EventerConfig)
 	require.NoError(t, err)
 
@@ -945,10 +926,6 @@ func Test_WriteAudit(t *testing.T) {
 		c := event.TestEventerConfig(t, "WriteAudit")
 		c.EventerConfig.AuditEnabled = false
 		testLock := &sync.Mutex{}
-		testLogger := hclog.New(&hclog.LoggerOptions{
-			Mutex: testLock,
-			Name:  "test",
-		})
 		e, err := event.NewEventer(testLogger, testLock, "not-enabled", c.EventerConfig)
 		require.NoError(err)
 
@@ -971,10 +948,7 @@ func Test_WriteError(t *testing.T) {
 
 	c := event.TestEventerConfig(t, "WriteAudit")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	e, err := event.NewEventer(testLogger, testLock, "Test_WriteError", c.EventerConfig, event.WithNow(now))
 	require.NoError(t, err)
 
@@ -1141,10 +1115,7 @@ func Test_WriteSysEvent(t *testing.T) {
 	ctx := context.Background()
 	c := event.TestEventerConfig(t, "Test_WriteSysEvent")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 
 	tests := []struct {
 		name         string
@@ -1297,3 +1268,12 @@ type testIntKeyWithStringer int
 func (ti testIntKeyWithStringer) String() string {
 	return fmt.Sprint("*", int(ti), "*")
 }
+
+func testLogger(t *testing.T, testLock hclog.Locker) hclog.Logger {
+	t.Helper()
+	return hclog.New(&hclog.LoggerOptions{
+		Mutex:      testLock,
+		Name:       "test",
+		JSONFormat: true,
+	})
+}

internal/observability/event/eventer.go

@@ -97,10 +97,45 @@ type pipeline struct {
 }
 
 var (
-	sysEventer     *Eventer     // sysEventer is the system-wide Eventer
-	sysEventerLock sync.RWMutex // sysEventerLock allows the sysEventer to safely be written concurrently.
+	sysEventer        *Eventer     // sysEventer is the system-wide Eventer
+	sysEventerLock    sync.RWMutex // sysEventerLock allows the sysEventer to safely be written concurrently.
+	sysFallbackLogger struct {
+		mu     sync.RWMutex
+		logger hclog.Logger
+	}
 )
 
+func defaultLogger() hclog.Logger {
+	opts := hclog.DefaultOptions
+	opts.JSONFormat = true
+	return hclog.New(opts)
+}
+
+// fallbackLogger returns the current fallback logger for eventing.  If there's
+// no current fallback logger, then a default logger is returned.
+func fallbackLogger() hclog.Logger {
+	sysFallbackLogger.mu.RLock()
+	defer sysFallbackLogger.mu.RUnlock()
+	if sysFallbackLogger.logger == nil {
+		return defaultLogger()
+	}
+	return sysFallbackLogger.logger
+}
+
+// InitFallbackLogger will initialize the fallback logger for eventing
+func InitFallbackLogger(l hclog.Logger) error {
+	const op = "event.InitFallbackLogger"
+	if isNil(l) {
+		return fmt.Errorf("%s: missing logger: %w", op, ErrInvalidParameter)
+	}
+
+	sysFallbackLogger.mu.Lock()
+	defer sysFallbackLogger.mu.Unlock()
+	sysFallbackLogger.logger = l
+
+	return nil
+}
+
 // InitSysEventer provides a mechanism to initialize a "system wide" eventer
 // singleton for Boundary.  Support the options of: WithEventer(...) and
 // WithEventerConfig(...)
@@ -884,3 +919,14 @@ func (s *logAdapter) pickType(str string) (Type, string) {
 		return SystemType, str
 	}
 }
+
+func isNil(i interface{}) bool {
+	if i == nil {
+		return true
+	}
+	switch reflect.TypeOf(i).Kind() {
+	case reflect.Ptr, reflect.Map, reflect.Array, reflect.Chan, reflect.Slice:
+		return reflect.ValueOf(i).IsNil()
+	}
+	return false
+}

internal/observability/event/eventer_gate_test.go

@@ -8,7 +8,6 @@ import (
 	"sync"
 	"testing"
 
-	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-secure-stdlib/strutil"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -36,10 +35,8 @@ func TestEventer_Gating(t *testing.T) {
 		},
 	}
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
+
 	eventer, err := NewEventer(
 		testLogger,
 		testLock,

internal/observability/event/eventer_retry_test.go

@@ -8,7 +8,6 @@ import (
 	"testing"
 
 	"github.com/hashicorp/eventlogger"
-	"github.com/hashicorp/go-hclog"
 	"github.com/hashicorp/go-multierror"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
@@ -21,9 +20,8 @@ func TestEventer_retrySend(t *testing.T) {
 	testConfig := TestEventerConfig(t, "TestEventer_retrySend")
 
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-	})
+	testLogger := testLogger(t, testLock)
+
 	eventer, err := NewEventer(testLogger, testLock, "TestEventer_retrySend", testConfig.EventerConfig)
 	require.NoError(t, err)
 

internal/observability/event/eventer_test.go

@@ -27,7 +27,8 @@ func Test_InitSysEventer(t *testing.T) {
 	testConfig := TestEventerConfig(t, "InitSysEventer")
 	testLock := &sync.Mutex{}
 	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
+		Mutex:      testLock,
+		JSONFormat: true,
 	})
 	testEventer, err := NewEventer(testLogger, testLock, "Test_InitSysEventer", testConfig.EventerConfig)
 	require.NoError(t, err)
@@ -164,9 +165,8 @@ func TestEventer_writeObservation(t *testing.T) {
 	ctx := context.Background()
 	testSetup := TestEventerConfig(t, "TestEventer_writeObservation")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-	})
+	testLogger := testLogger(t, testLock)
+
 	eventer, err := NewEventer(testLogger, testLock, "TestEventer_writeObservation", testSetup.EventerConfig)
 	require.NoError(t, err)
 
@@ -219,11 +219,7 @@ func TestEventer_writeObservation(t *testing.T) {
 		c := EventerConfig{
 			ObservationsEnabled: true,
 		}
-		testLock := &sync.Mutex{}
-		testLogger := hclog.New(&hclog.LoggerOptions{
-			Mutex: testLock,
-			Name:  "test",
-		})
+
 		// with no defined config, it will default to a stderr sink
 		e, err := NewEventer(testLogger, testLock, "e2e-test", c)
 		require.NoError(err)
@@ -244,10 +240,7 @@ func TestEventer_writeAudit(t *testing.T) {
 	ctx := context.Background()
 	testSetup := TestEventerConfig(t, "Test_NewEventer")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 	eventer, err := NewEventer(testLogger, testLock, "TestEventer_writeAudit", testSetup.EventerConfig)
 	require.NoError(t, err)
 
@@ -304,10 +297,8 @@ func TestEventer_writeError(t *testing.T) {
 	ctx := context.Background()
 	testSetup := TestEventerConfig(t, "Test_NewEventer")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
+
 	eventer, er := NewEventer(testLogger, testLock, "TestEventer_writeError", testSetup.EventerConfig)
 	require.NoError(t, er)
 
@@ -363,10 +354,7 @@ func Test_NewEventer(t *testing.T) {
 	testHclogSetup := TestEventerConfig(t, "Test_NewEventer", testWithSinkFormat(t, TextHclogSinkFormat))
 
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 
 	twrapper := testWrapper(t)
 
@@ -772,10 +760,7 @@ func TestEventer_Reopen(t *testing.T) {
 		assert, require := assert.New(t), require.New(t)
 
 		testLock := &sync.Mutex{}
-		testLogger := hclog.New(&hclog.LoggerOptions{
-			Mutex: testLock,
-			Name:  "test",
-		})
+		testLogger := testLogger(t, testLock)
 
 		e, err := NewEventer(testLogger, testLock, "TestEventer_Reopen", EventerConfig{})
 		require.NoError(err)
@@ -794,10 +779,7 @@ func TestEventer_FlushNodes(t *testing.T) {
 	t.Run("simple", func(t *testing.T) {
 		assert, require := assert.New(t), require.New(t)
 		testLock := &sync.Mutex{}
-		testLogger := hclog.New(&hclog.LoggerOptions{
-			Mutex: testLock,
-			Name:  "test",
-		})
+		testLogger := testLogger(t, testLock)
 
 		e, err := NewEventer(testLogger, testLock, "TestEventer_FlushNodes", EventerConfig{})
 		require.NoError(err)
@@ -832,10 +814,8 @@ func Test_StandardLogger(t *testing.T) {
 	testCtx := context.Background()
 	c := TestEventerConfig(t, "Test_StandardLogger")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
+
 	require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
 
 	tests := []struct {
@@ -923,10 +903,8 @@ func Test_StandardWriter(t *testing.T) {
 
 	c := TestEventerConfig(t, "Test_StandardLogger")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
+
 	require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
 
 	testCtx, err := NewEventerContext(context.Background(), SysEventer())
@@ -1017,10 +995,8 @@ func Test_logAdapter_Write(t *testing.T) {
 
 	c := TestEventerConfig(t, "Test_StandardLogger")
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
+
 	require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
 
 	testCtx, err := NewEventerContext(context.Background(), SysEventer())
@@ -1177,10 +1153,7 @@ func TestEventer_RotateAuditWrapper(t *testing.T) {
 	hclogConfig := TestEventerConfig(t, "TestEventer_RotateAuditWrapper", testWithSinkFormat(t, JSONHclogSinkFormat))
 
 	testLock := &sync.Mutex{}
-	testLogger := hclog.New(&hclog.LoggerOptions{
-		Mutex: testLock,
-		Name:  "test",
-	})
+	testLogger := testLogger(t, testLock)
 
 	testCtx := context.Background()
 	tests := []struct {

internal/observability/event/testing.go

@@ -315,3 +315,12 @@ func (b *testMockBroker) SetSuccessThreshold(t eventlogger.EventType, successThr
 	b.successThresholds[t] = successThreshold
 	return nil
 }
+
+func testLogger(t *testing.T, testLock hclog.Locker) hclog.Logger {
+	t.Helper()
+	return hclog.New(&hclog.LoggerOptions{
+		Mutex:      testLock,
+		Name:       "test",
+		JSONFormat: true,
+	})
+}