mirror of https://github.com/hashicorp/boundary
Add hclog adapter and gating to eventer (#1915)
This contains to related things: 1. An adapter allowing an hclog interface to take in information and send them to the eventer 2. A gate on the eventer, which is the analogue to the behavior prior to eventing where we'd ensure logs were not printed prior to the startup information. Without this, plugin logs using the hclog adapter will start showing up too early.pull/1928/head
Jeff Mitchell
4 years ago
committed by
GitHub
parent
7eb29261b2
commit
e596daf34d
@ -0,0 +1,166 @@
|
||||
package event
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"fmt"
|
||||
"os"
|
||||
"strings"
|
||||
"sync"
|
||||
"testing"
|
||||
|
||||
"github.com/hashicorp/boundary/globals"
|
||||
"github.com/hashicorp/go-hclog"
|
||||
"github.com/hashicorp/go-secure-stdlib/strutil"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
)
|
||||
|
||||
func TestEventer_Gating(t *testing.T) {
|
||||
t.Parallel()
|
||||
require := require.New(t)
|
||||
|
||||
// FIXME: Remove this when no longer needed:
|
||||
os.Setenv(globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS, "true")
|
||||
|
||||
buffer := new(bytes.Buffer)
|
||||
eventerConfig := EventerConfig{
|
||||
AuditEnabled: true,
|
||||
ObservationsEnabled: true,
|
||||
SysEventsEnabled: true,
|
||||
Sinks: []*SinkConfig{
|
||||
{
|
||||
Name: "test-sink",
|
||||
EventTypes: []Type{EveryType},
|
||||
Format: TextHclogSinkFormat,
|
||||
Type: WriterSink,
|
||||
WriterConfig: &WriterSinkTypeConfig{
|
||||
Writer: buffer,
|
||||
},
|
||||
},
|
||||
},
|
||||
}
|
||||
testLock := &sync.Mutex{}
|
||||
testLogger := hclog.New(&hclog.LoggerOptions{
|
||||
Mutex: testLock,
|
||||
Name: "test",
|
||||
})
|
||||
eventer, err := NewEventer(
|
||||
testLogger,
|
||||
testLock,
|
||||
"TestEventer_Gating",
|
||||
eventerConfig,
|
||||
WithGating(true),
|
||||
)
|
||||
require.NoError(err)
|
||||
|
||||
ctx, err := NewEventerContext(context.Background(), eventer)
|
||||
require.NoError(err)
|
||||
|
||||
// This test sends a series of events of different types. The tests are
|
||||
// meant to be in order as we want to send some that should be gated and
|
||||
// some that shouldn't and ensure correct behavior at each step.
|
||||
var totalEvents int
|
||||
tests := []struct {
|
||||
name string
|
||||
eventFn func()
|
||||
expectedGatedEvents int
|
||||
}{
|
||||
{
|
||||
name: "system-event-1",
|
||||
eventFn: func() {
|
||||
WriteSysEvent(ctx, "system-event-1", "system-event-1")
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 1,
|
||||
},
|
||||
{
|
||||
name: "system-event-2",
|
||||
eventFn: func() {
|
||||
WriteSysEvent(ctx, "system-event-2", "system-event-2")
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 2,
|
||||
},
|
||||
{
|
||||
name: "audit-1",
|
||||
eventFn: func() {
|
||||
require.NoError(WriteAudit(ctx, "audit-1"))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 2,
|
||||
},
|
||||
{
|
||||
name: "observation-1",
|
||||
eventFn: func() {
|
||||
require.NoError(WriteObservation(ctx, "observation-1", WithId("observation-1"), WithHeader("foo", "bar")))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 2,
|
||||
},
|
||||
{
|
||||
name: "error-1",
|
||||
eventFn: func() {
|
||||
WriteError(ctx, "error-1", fmt.Errorf("error-1"))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 3,
|
||||
},
|
||||
{
|
||||
name: "error-2",
|
||||
eventFn: func() {
|
||||
WriteError(ctx, "error-2", fmt.Errorf("error-2"))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 4,
|
||||
},
|
||||
// This should result in all events being flushed so none gated
|
||||
{
|
||||
name: "release-gate",
|
||||
eventFn: func() {
|
||||
require.NoError(eventer.ReleaseGate())
|
||||
},
|
||||
expectedGatedEvents: 0,
|
||||
},
|
||||
// From here on out we're verifying that all events of all types go through
|
||||
{
|
||||
name: "system-event-3",
|
||||
eventFn: func() {
|
||||
WriteSysEvent(ctx, "system-event-3", "system-event-3")
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 0,
|
||||
},
|
||||
{
|
||||
name: "audit-2",
|
||||
eventFn: func() {
|
||||
require.NoError(WriteAudit(ctx, "audit-2"))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 0,
|
||||
},
|
||||
{
|
||||
name: "observation-2",
|
||||
eventFn: func() {
|
||||
require.NoError(WriteObservation(ctx, "observation-2", WithId("observation-2"), WithHeader("foo", "bar")))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 0,
|
||||
},
|
||||
{
|
||||
name: "error-2",
|
||||
eventFn: func() {
|
||||
WriteError(ctx, "error-2", fmt.Errorf("error-2"))
|
||||
totalEvents++
|
||||
},
|
||||
expectedGatedEvents: 0,
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
assert := assert.New(t)
|
||||
tt.eventFn()
|
||||
assert.Len(strutil.RemoveEmpty(strings.Split(buffer.String(), "\n")), totalEvents-tt.expectedGatedEvents, buffer.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
@ -0,0 +1,237 @@
|
||||
package event
|
||||
|
||||
import (
|
||||
"context"
|
||||
"fmt"
|
||||
"io"
|
||||
"log"
|
||||
"sync"
|
||||
|
||||
"github.com/hashicorp/go-hclog"
|
||||
)
|
||||
|
||||
// HclogLoggerAdapter is used to provide an hclog-style interface to code that
|
||||
// cannot natively handle eventing. Currently, all log lines are written as
|
||||
// system events. Note that this is not meant for high throughput; some
|
||||
// potential optimizations (such as using atomic values for name and such) are
|
||||
// not current implemented. Additionally, some functions (such as fetching a
|
||||
// stdlib logger/writer) are simply not supported right now.
|
||||
type HclogLoggerAdapter struct {
|
||||
eventCtx context.Context
|
||||
l *sync.RWMutex
|
||||
level hclog.Level
|
||||
name string
|
||||
withArgs []interface{}
|
||||
}
|
||||
|
||||
// Ensure that we are implementing Logger
|
||||
var _ hclog.Logger = (*HclogLoggerAdapter)(nil)
|
||||
|
||||
// NewHclogLogger creates a new hclog.Logger-compatible implementation that
|
||||
// outputs to events
|
||||
func NewHclogLogger(ctx context.Context, e *Eventer, opt ...Option) (hclog.Logger, error) {
|
||||
const op = "event.HclogLogger"
|
||||
eventCtx, err := NewEventerContext(ctx, e)
|
||||
if err != nil {
|
||||
return nil, fmt.Errorf("%s: %w", op, err)
|
||||
}
|
||||
opts := getOpts(opt...)
|
||||
return &HclogLoggerAdapter{
|
||||
eventCtx: eventCtx,
|
||||
l: new(sync.RWMutex),
|
||||
level: opts.withHclogLevel,
|
||||
}, nil
|
||||
}
|
||||
|
||||
// Args are alternating key, val pairs
|
||||
// keys must be strings
|
||||
// vals can be any type, but display is implementation specific
|
||||
// Emit a message and key/value pairs at a provided log level
|
||||
func (h *HclogLoggerAdapter) Log(level hclog.Level, msg string, args ...interface{}) {
|
||||
switch {
|
||||
case h.level == hclog.NoLevel: // If logger is not set to any level, accept it
|
||||
case h.level <= level: // Otherwise if logger is same or more verbose, accept
|
||||
default:
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
// Emit a message and key/value pairs at the TRACE level
|
||||
func (h *HclogLoggerAdapter) Trace(msg string, args ...interface{}) {
|
||||
if h.level > hclog.Trace {
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
// Emit a message and key/value pairs at the DEBUG level
|
||||
func (h *HclogLoggerAdapter) Debug(msg string, args ...interface{}) {
|
||||
if h.level > hclog.Debug {
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
// Emit a message and key/value pairs at the INFO level
|
||||
func (h *HclogLoggerAdapter) Info(msg string, args ...interface{}) {
|
||||
if h.level > hclog.Info {
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
// Emit a message and key/value pairs at the WARN level
|
||||
func (h *HclogLoggerAdapter) Warn(msg string, args ...interface{}) {
|
||||
if h.level > hclog.Warn {
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
// Emit a message and key/value pairs at the ERROR level
|
||||
func (h *HclogLoggerAdapter) Error(msg string, args ...interface{}) {
|
||||
if h.level > hclog.Error {
|
||||
return
|
||||
}
|
||||
h.writeEvent("", msg, args)
|
||||
}
|
||||
|
||||
func (h *HclogLoggerAdapter) writeEvent(caller Op, msg string, args []interface{}) {
|
||||
h.l.RLock()
|
||||
defer h.l.RUnlock()
|
||||
var allArgs []interface{}
|
||||
if len(h.withArgs)+len(args) > 0 {
|
||||
allArgs = append(h.withArgs, args...)
|
||||
}
|
||||
if h.name != "" {
|
||||
allArgs = append(allArgs, "@original-log-name", h.name)
|
||||
}
|
||||
allArgs = append(allArgs, "@original-log-level", h.level.String())
|
||||
WriteSysEvent(h.eventCtx, "", msg, allArgs...)
|
||||
}
|
||||
|
||||
// Indicate if TRACE logs would be emitted. This and the other Is* guards
|
||||
// are used to elide expensive logging code based on the current level.
|
||||
func (h *HclogLoggerAdapter) IsTrace() bool {
|
||||
return h.level <= hclog.Trace
|
||||
}
|
||||
|
||||
// Indicate if DEBUG logs would be emitted. This and the other Is* guards
|
||||
func (h *HclogLoggerAdapter) IsDebug() bool {
|
||||
return h.level <= hclog.Debug
|
||||
}
|
||||
|
||||
// Indicate if INFO logs would be emitted. This and the other Is* guards
|
||||
func (h *HclogLoggerAdapter) IsInfo() bool {
|
||||
return h.level <= hclog.Info
|
||||
}
|
||||
|
||||
// Indicate if WARN logs would be emitted. This and the other Is* guards
|
||||
func (h *HclogLoggerAdapter) IsWarn() bool {
|
||||
return h.level <= hclog.Warn
|
||||
}
|
||||
|
||||
// Indicate if ERROR logs would be emitted. This and the other Is* guards
|
||||
func (h *HclogLoggerAdapter) IsError() bool {
|
||||
return h.level <= hclog.Error
|
||||
}
|
||||
|
||||
// ImpliedArgs returns With key/value pairs
|
||||
func (h *HclogLoggerAdapter) ImpliedArgs() []interface{} {
|
||||
return h.withArgs
|
||||
}
|
||||
|
||||
// Creates a sublogger that will always have the given key/value pairs
|
||||
func (h *HclogLoggerAdapter) With(args ...interface{}) hclog.Logger {
|
||||
h.l.Lock()
|
||||
defer h.l.Unlock()
|
||||
newArgs := args
|
||||
if len(h.withArgs) > 0 {
|
||||
newArgs = make([]interface{}, len(h.withArgs), len(h.withArgs)+len(args))
|
||||
copy(newArgs, h.withArgs)
|
||||
newArgs = append(newArgs, args...)
|
||||
}
|
||||
return &HclogLoggerAdapter{
|
||||
eventCtx: h.eventCtx,
|
||||
l: new(sync.RWMutex),
|
||||
level: h.level,
|
||||
name: h.name,
|
||||
withArgs: newArgs,
|
||||
}
|
||||
}
|
||||
|
||||
// Returns the Name of the logger
|
||||
func (h *HclogLoggerAdapter) Name() string {
|
||||
h.l.RLock()
|
||||
defer h.l.RUnlock()
|
||||
return h.name
|
||||
}
|
||||
|
||||
// Create a logger that will prepend the name string on the front of all messages.
|
||||
// If the logger already has a name, the new value will be appended to the current
|
||||
// name. That way, a major subsystem can use this to decorate all it's own logs
|
||||
// without losing context.
|
||||
func (h *HclogLoggerAdapter) Named(name string) hclog.Logger {
|
||||
h.l.Lock()
|
||||
defer h.l.Unlock()
|
||||
var newArgs []interface{}
|
||||
if len(h.withArgs) > 0 {
|
||||
newArgs = make([]interface{}, len(h.withArgs))
|
||||
copy(newArgs, h.withArgs)
|
||||
}
|
||||
|
||||
newName := name
|
||||
if h.name != "" {
|
||||
newName = fmt.Sprintf("%s.%s", h.name, name)
|
||||
}
|
||||
|
||||
return &HclogLoggerAdapter{
|
||||
eventCtx: h.eventCtx,
|
||||
l: new(sync.RWMutex),
|
||||
level: h.level,
|
||||
name: newName,
|
||||
withArgs: newArgs,
|
||||
}
|
||||
}
|
||||
|
||||
// Create a logger that will prepend the name string on the front of all messages.
|
||||
// This sets the name of the logger to the value directly, unlike Named which honor
|
||||
// the current name as well.
|
||||
func (h *HclogLoggerAdapter) ResetNamed(name string) hclog.Logger {
|
||||
h.l.Lock()
|
||||
defer h.l.Unlock()
|
||||
var newArgs []interface{}
|
||||
if len(h.withArgs) > 0 {
|
||||
newArgs = make([]interface{}, len(h.withArgs))
|
||||
copy(newArgs, h.withArgs)
|
||||
}
|
||||
return &HclogLoggerAdapter{
|
||||
eventCtx: h.eventCtx,
|
||||
l: new(sync.RWMutex),
|
||||
level: h.level,
|
||||
name: name,
|
||||
withArgs: newArgs,
|
||||
}
|
||||
}
|
||||
|
||||
// Updates the level. This should affect all related loggers as well,
|
||||
// unless they were created with IndependentLevels. If an
|
||||
// implementation cannot update the level on the fly, it should no-op.
|
||||
//
|
||||
// This implementation is a no-op currently.
|
||||
func (h *HclogLoggerAdapter) SetLevel(_ hclog.Level) {}
|
||||
|
||||
// Return a value that conforms to the stdlib log.Logger interface
|
||||
//
|
||||
// This implementation does not currently support this and returns nil.
|
||||
func (h *HclogLoggerAdapter) StandardLogger(opts *hclog.StandardLoggerOptions) *log.Logger {
|
||||
return nil
|
||||
}
|
||||
|
||||
// Return a value that conforms to io.Writer, which can be passed into log.SetOutput()
|
||||
//
|
||||
// This implementation does not currently support this and returns nil.
|
||||
func (h *HclogLoggerAdapter) StandardWriter(opts *hclog.StandardLoggerOptions) io.Writer {
|
||||
return nil
|
||||
}
|
||||
@ -0,0 +1,186 @@
|
||||
package event
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"context"
|
||||
"sync"
|
||||
"testing"
|
||||
|
||||
"github.com/hashicorp/go-hclog"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
)
|
||||
|
||||
func TestEventer_HclogLoggerAdapter(t *testing.T) {
|
||||
t.Parallel()
|
||||
require := require.New(t)
|
||||
ctx := context.Background()
|
||||
buffer := new(bytes.Buffer)
|
||||
eventerConfig := EventerConfig{
|
||||
AuditEnabled: true,
|
||||
ObservationsEnabled: true,
|
||||
SysEventsEnabled: true,
|
||||
Sinks: []*SinkConfig{
|
||||
{
|
||||
Name: "test-sink",
|
||||
EventTypes: []Type{EveryType},
|
||||
Format: TextHclogSinkFormat,
|
||||
Type: WriterSink,
|
||||
WriterConfig: &WriterSinkTypeConfig{
|
||||
Writer: buffer,
|
||||
},
|
||||
},
|
||||
},
|
||||
}
|
||||
testLock := &sync.Mutex{}
|
||||
testLogger := hclog.New(&hclog.LoggerOptions{
|
||||
Mutex: testLock,
|
||||
Name: "test",
|
||||
})
|
||||
eventer, err := NewEventer(
|
||||
testLogger,
|
||||
testLock,
|
||||
"TestEventer_HclogLoggerAdapter",
|
||||
eventerConfig,
|
||||
)
|
||||
require.NoError(err)
|
||||
|
||||
// This test sends a series of events through the hclog adapter and
|
||||
// validates that we see the ones we expect to see on the other side. It
|
||||
// also tests various features such as Named and With to ensure they turn
|
||||
// into values on the other side.
|
||||
logger, err := NewHclogLogger(ctx, eventer, WithHclogLevel(hclog.Info))
|
||||
require.NoError(err)
|
||||
|
||||
tests := []struct {
|
||||
name string
|
||||
plainLog bool
|
||||
level hclog.Level
|
||||
shouldNotLog bool
|
||||
logOverride hclog.Logger
|
||||
input string
|
||||
outputSubstrs []string
|
||||
}{
|
||||
{
|
||||
name: "over-level-error",
|
||||
level: hclog.Error,
|
||||
input: "over-error",
|
||||
outputSubstrs: []string{"msg=over-error"},
|
||||
},
|
||||
{
|
||||
name: "over-level-warn",
|
||||
level: hclog.Warn,
|
||||
input: "over-warn",
|
||||
outputSubstrs: []string{"msg=over-warn"},
|
||||
},
|
||||
{
|
||||
name: "at-level",
|
||||
level: hclog.Info,
|
||||
input: "at",
|
||||
outputSubstrs: []string{"msg=at"},
|
||||
},
|
||||
{
|
||||
name: "under-level-debug",
|
||||
level: hclog.Debug,
|
||||
input: "under-debug",
|
||||
shouldNotLog: true,
|
||||
},
|
||||
{
|
||||
name: "under-level-trace",
|
||||
level: hclog.Trace,
|
||||
input: "under-trace",
|
||||
shouldNotLog: true,
|
||||
},
|
||||
{
|
||||
name: "plain-under-trace",
|
||||
plainLog: true,
|
||||
level: hclog.Trace,
|
||||
input: "plain-under-trace",
|
||||
shouldNotLog: true,
|
||||
},
|
||||
{
|
||||
name: "plain-at",
|
||||
plainLog: true,
|
||||
level: hclog.Info,
|
||||
input: "plain-at",
|
||||
outputSubstrs: []string{"msg=plain-at"},
|
||||
},
|
||||
{
|
||||
name: "plain-over-warn",
|
||||
plainLog: true,
|
||||
level: hclog.Warn,
|
||||
input: "plain-over-warn",
|
||||
outputSubstrs: []string{"msg=plain-over-warn"},
|
||||
},
|
||||
{
|
||||
name: "with-named",
|
||||
level: hclog.Info,
|
||||
logOverride: logger.Named("named-logger"),
|
||||
input: "named-input",
|
||||
outputSubstrs: []string{"msg=named-input", "@original-log-name=named-logger"},
|
||||
},
|
||||
{
|
||||
name: "sub-named",
|
||||
level: hclog.Info,
|
||||
logOverride: logger.Named("named-logger").Named("subnamed-logger"),
|
||||
input: "subnamed-input",
|
||||
outputSubstrs: []string{"msg=subnamed-input", "@original-log-name=named-logger.subnamed-logger"},
|
||||
},
|
||||
{
|
||||
name: "reset-named",
|
||||
level: hclog.Info,
|
||||
logOverride: logger.Named("named-logger").ResetNamed("reset-logger"),
|
||||
input: "reset-input",
|
||||
outputSubstrs: []string{"msg=reset-input", "@original-log-name=reset-logger"},
|
||||
},
|
||||
{
|
||||
name: "with-params",
|
||||
level: hclog.Info,
|
||||
logOverride: logger.With("with", "params"),
|
||||
input: "with-params",
|
||||
outputSubstrs: []string{"msg=with-params", "with=params"},
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
assert := assert.New(t)
|
||||
buffer.Reset()
|
||||
loggerToUse := logger
|
||||
if tt.logOverride != nil {
|
||||
loggerToUse = tt.logOverride
|
||||
}
|
||||
|
||||
switch tt.plainLog {
|
||||
case false:
|
||||
switch tt.level {
|
||||
case hclog.Error:
|
||||
assert.True(loggerToUse.IsError() == !tt.shouldNotLog)
|
||||
loggerToUse.Error(tt.input)
|
||||
case hclog.Warn:
|
||||
assert.True(loggerToUse.IsWarn() == !tt.shouldNotLog)
|
||||
loggerToUse.Warn(tt.input)
|
||||
case hclog.Info:
|
||||
assert.True(loggerToUse.IsInfo() == !tt.shouldNotLog)
|
||||
loggerToUse.Info(tt.input)
|
||||
case hclog.Debug:
|
||||
assert.True(loggerToUse.IsDebug() == !tt.shouldNotLog)
|
||||
loggerToUse.Debug(tt.input)
|
||||
case hclog.Trace:
|
||||
assert.True(loggerToUse.IsTrace() == !tt.shouldNotLog)
|
||||
loggerToUse.Trace(tt.input)
|
||||
}
|
||||
default:
|
||||
loggerToUse.Log(tt.level, tt.input)
|
||||
}
|
||||
|
||||
switch tt.shouldNotLog {
|
||||
case true:
|
||||
assert.Len(buffer.String(), 0)
|
||||
default:
|
||||
for _, substr := range tt.outputSubstrs {
|
||||
assert.Contains(buffer.String(), substr)
|
||||
}
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
Loading…
Reference in new issue