Event log adpaters (#1434)

pull/1436/head
Jim 5 years ago committed by GitHub
parent 68dd2a66ba
commit 137729b0c0
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

@ -82,7 +82,10 @@ Canonical reference for changes, improvements, and bugfixes for Boundary.
redacting/encrypting that data.
PRs: [update eventlogger](https://github.com/hashicorp/boundary/pull/1411),
PRs:
[log adapters](https://github.com/hashicorp/boundary/pull/1434),
[unneeded log deps](https://github.com/hashicorp/boundary/pull/1433),
[update eventlogger](https://github.com/hashicorp/boundary/pull/1411),
[convert from hclog to events](https://github.com/hashicorp/boundary/pull/1409),
[event filtering](https://github.com/hashicorp/boundary/pull/1404),
[cloudevents node](https://github.com/hashicorp/boundary/pull/1390),

@ -6,6 +6,7 @@ import (
"fmt"
"net"
"net/url"
"runtime"
"strings"
"github.com/hashicorp/boundary/internal/auth/oidc"
@ -262,10 +263,6 @@ func (b *Server) CreateDevOidcAuthMethod(ctx context.Context) error {
// Create the subject information and testing provider
{
logger, err := capoidc.NewTestingLogger(b.Logger.Named("dev-oidc"))
if err != nil {
return fmt.Errorf("unable to create logger: %w", err)
}
subInfo := map[string]*capoidc.TestSubject{
b.DevLoginName: {
@ -289,7 +286,7 @@ func (b *Server) CreateDevOidcAuthMethod(ctx context.Context) error {
clientSecret := string(b.DevOidcSetup.clientSecret)
b.DevOidcSetup.testProvider = capoidc.StartTestProvider(
logger,
&oidcLogger{},
capoidc.WithNoTLS(),
capoidc.WithTestHost(b.DevOidcSetup.hostAddr),
capoidc.WithTestPort(b.DevOidcSetup.oidcPort),
@ -443,3 +440,35 @@ func (b *Server) createInitialOidcAuthMethod(ctx context.Context) (*oidc.AuthMet
return nil, nil
}
// oidcLogger satisfies the interface requirements for the oidc.TestProvider logger.
type oidcLogger struct {
Ctx context.Context // nil ctx is allowed/okay
}
// Errorf will use the sys eventer to emit an error event
func (l *oidcLogger) Errorf(format string, args ...interface{}) {
event.WriteError(l.Ctx, l.caller(), fmt.Errorf(format, args...))
}
// Infof will use the sys eventer to emit an system event
func (l *oidcLogger) Infof(format string, args ...interface{}) {
event.WriteSysEvent(l.Ctx, l.caller(), fmt.Sprintf(format, args...))
}
// FailNow will panic (as required by the interface it's implementing)
func (_ *oidcLogger) FailNow() {
panic("sys eventer failed, see logs for output (if any)")
}
func (_ *oidcLogger) caller() event.Op {
var caller event.Op
pc, _, _, ok := runtime.Caller(2)
details := runtime.FuncForPC(pc)
if ok && details != nil {
caller = event.Op(details.Name())
} else {
caller = "unknown operation"
}
return caller
}

@ -0,0 +1,113 @@
package base
import (
"encoding/json"
"fmt"
"io/ioutil"
"os"
"sync"
"testing"
"github.com/hashicorp/boundary/internal/observability/event"
"github.com/hashicorp/eventlogger/formatter_filters/cloudevents"
"github.com/hashicorp/go-hclog"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
func Test_oidcLogger_Errorf(t *testing.T) {
// this test and its subtests cannot be run in parallel because of it's
// dependency on the sysEventer
c := event.TestEventerConfig(t, "TestoidcLogger_Errorf")
testLock := &sync.Mutex{}
testLogger := hclog.New(&hclog.LoggerOptions{
Mutex: testLock,
Name: "test",
})
require.NoError(t, event.InitSysEventer(testLogger, testLock, "use-TestoidcLogger_Errorf", event.WithEventerConfig(&c.EventerConfig)))
tests := []struct {
name string
fmt string
args []interface{}
}{
{
name: "no-args",
fmt: "simple",
},
{
name: "with-args",
fmt: "%s: simple",
args: []interface{}{"error"},
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
assert, require := assert.New(t), require.New(t)
l := &oidcLogger{}
l.Errorf(tt.fmt, tt.args...)
sinkFileName := c.AllEvents.Name()
defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }()
b, err := ioutil.ReadFile(sinkFileName)
require.NoError(err)
gotEvent := &cloudevents.Event{}
err = json.Unmarshal(b, gotEvent)
require.NoErrorf(err, "json: %s", string(b))
expected := gotEvent.Data.(map[string]interface{})
expected["error"] = fmt.Sprintf(tt.fmt, tt.args...)
assert.Equal(expected, gotEvent.Data.(map[string]interface{}))
})
}
}
func Test_oidcLogger_Infof(t *testing.T) {
// this test and its subtests cannot be run in parallel because of it's
// dependency on the sysEventer
c := event.TestEventerConfig(t, "TestoidcLogger_Errorf")
testLock := &sync.Mutex{}
testLogger := hclog.New(&hclog.LoggerOptions{
Mutex: testLock,
Name: "test",
})
require.NoError(t, event.InitSysEventer(testLogger, testLock, "use-TestoidcLogger_Errorf", event.WithEventerConfig(&c.EventerConfig)))
tests := []struct {
name string
fmt string
args []interface{}
}{
{
name: "no-args",
fmt: "simple",
},
{
name: "with-args",
fmt: "%s: simple",
args: []interface{}{"info"},
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
assert, require := assert.New(t), require.New(t)
l := &oidcLogger{}
l.Infof(tt.fmt, tt.args...)
sinkFileName := c.AllEvents.Name()
defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }()
b, err := ioutil.ReadFile(sinkFileName)
require.NoError(err)
gotEvent := &cloudevents.Event{}
err = json.Unmarshal(b, gotEvent)
require.NoErrorf(err, "json: %s", string(b))
expected := gotEvent.Data.(map[string]interface{})
expected["msg"] = fmt.Sprintf(tt.fmt, tt.args...)
assert.Equal(expected, gotEvent.Data.(map[string]interface{}))
})
}
}
func Test_oidcLogger_FailNow(t *testing.T) {
l := &oidcLogger{}
assert.Panics(t, func() { l.FailNow() }, "sys eventer failed, see logs for output (if any)")
}

@ -1,10 +1,16 @@
package event
import (
"bytes"
"context"
"errors"
"fmt"
"io"
"log"
"net/url"
"os"
"runtime"
"strings"
"sync"
"time"
@ -551,3 +557,129 @@ func (e *Eventer) FlushNodes(ctx context.Context) error {
}
return nil
}
// StandardLogger will create *log.Logger that will emit events through this
// Logger. This allows packages that require the stdlib log to emit events
// instead.
func (e *Eventer) StandardLogger(ctx context.Context, loggerName string, typ Type) (*log.Logger, error) {
const op = "event.(Eventer).StandardLogger"
if e == nil {
return nil, fmt.Errorf("%s: nil eventer: %w", op, ErrInvalidParameter)
}
if ctx == nil {
return nil, fmt.Errorf("%s: missing context: %w", op, ErrInvalidParameter)
}
if typ == "" {
return nil, fmt.Errorf("%s: missing type: %w", op, ErrInvalidParameter)
}
w, err := e.StandardWriter(ctx, typ)
if err != nil {
return nil, fmt.Errorf("%s: %w", op, err)
}
return log.New(w, loggerName, 0), nil
}
// StandardWriter will create an io.Writer that will emit events through this
// io.Writer.
func (e *Eventer) StandardWriter(ctx context.Context, typ Type) (io.Writer, error) {
const op = "event.(Eventer).StandardErrorWriter"
if e == nil {
return nil, fmt.Errorf("%s: nil eventer: %w", op, ErrInvalidParameter)
}
if ctx == nil {
return nil, fmt.Errorf("%s: missing context: %w", op, ErrInvalidParameter)
}
if typ == "" {
return nil, fmt.Errorf("%s: missing type: %w", op, ErrInvalidParameter)
}
if err := typ.validate(); err != nil {
return nil, fmt.Errorf("%s: %w", op, err)
}
newEventer := *e
ctx, err := NewEventerContext(ctx, e)
if err != nil {
return nil, fmt.Errorf("%s: %w", op, err)
}
return &logAdapter{
ctxWithEventer: ctx,
e: &newEventer,
emitEventType: typ,
}, nil
}
type logAdapter struct {
ctxWithEventer context.Context
e *Eventer
emitEventType Type
}
// Write satisfies the io.Writer interface and will take the data, infer the
// type of event and then emit an event.
func (s *logAdapter) Write(data []byte) (int, error) {
const op = "event.(stdlogAdapter).Write"
if s == nil {
return 0, fmt.Errorf("%s: nil log adapter: %w", op, ErrInvalidParameter)
}
var caller Op
pc, _, _, ok := runtime.Caller(1)
details := runtime.FuncForPC(pc)
if ok && details != nil {
caller = Op(details.Name())
} else {
caller = "unknown operation"
}
str := string(bytes.TrimRight(data, " \t\n"))
switch s.emitEventType {
case ErrorType, SystemType:
if err := s.send(s.emitEventType, caller, str); err != nil {
return 0, fmt.Errorf("%s: %w", op, err)
}
default:
t, str := s.pickType(str)
if err := s.send(t, caller, str); err != nil {
return 0, fmt.Errorf("%s: %w", op, err)
}
}
return len(data), nil
}
func (s *logAdapter) send(typ Type, caller Op, str string) error {
const op = "events.(stdlogAdapter).send"
if typ == "" {
return fmt.Errorf("%s: type is missing: %w", op, ErrInvalidParameter)
}
if caller == "" {
return fmt.Errorf("%s: missing caller: %w", op, ErrInvalidParameter)
}
switch typ {
case ErrorType:
WriteError(s.ctxWithEventer, caller, errors.New(str))
return nil
case SystemType:
WriteSysEvent(s.ctxWithEventer, caller, str)
return nil
default:
return fmt.Errorf("%s: unsupported event type %s: %w", op, typ, ErrInvalidParameter)
}
}
func (s *logAdapter) pickType(str string) (Type, string) {
switch {
case strings.HasPrefix(str, "[DEBUG]"):
return SystemType, strings.TrimSpace(str[7:])
case strings.HasPrefix(str, "[TRACE]"):
return SystemType, strings.TrimSpace(str[7:])
case strings.HasPrefix(str, "[INFO]"):
return SystemType, strings.TrimSpace(str[6:])
case strings.HasPrefix(str, "[WARN]"):
return SystemType, strings.TrimSpace(str[6:])
case strings.HasPrefix(str, "[ERROR]"):
return ErrorType, strings.TrimSpace(str[7:])
case strings.HasPrefix(str, "[ERR]"):
return ErrorType, strings.TrimSpace(str[5:])
default:
return SystemType, str
}
}

@ -2,12 +2,18 @@ package event
import (
"context"
"encoding/json"
"fmt"
"io"
"io/ioutil"
"log"
"os"
"strings"
"sync"
"testing"
"github.com/hashicorp/eventlogger"
"github.com/hashicorp/eventlogger/formatter_filters/cloudevents"
"github.com/hashicorp/go-hclog"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
@ -661,3 +667,347 @@ func (t *testFlushNode) FlushAll(_ context.Context) error {
}
return nil
}
func Test_StandardLogger(t *testing.T) {
// this test and its subtests cannot be run in parallel because of it's
// dependency on the sysEventer
testCtx := context.Background()
c := TestEventerConfig(t, "Test_StandardLogger")
testLock := &sync.Mutex{}
testLogger := hclog.New(&hclog.LoggerOptions{
Mutex: testLock,
Name: "test",
})
require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
tests := []struct {
name string
eventer *Eventer
ctx context.Context
eventType Type
wantErr bool
wantErrIs error
wantErrContains string
wantLogger *log.Logger
}{
{
name: "missing-eventer",
ctx: testCtx,
eventType: ErrorType,
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "nil eventer",
},
{
name: "missing-ctx",
eventer: SysEventer(),
eventType: ErrorType,
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "missing context",
},
{
name: "missing-type",
ctx: testCtx,
eventer: SysEventer(),
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "missing type",
},
{
name: "invalid-type",
ctx: testCtx,
eventer: SysEventer(),
eventType: "invalid",
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "'invalid' is not a valid event type",
},
{
name: "okay",
ctx: testCtx,
eventer: SysEventer(),
eventType: ErrorType,
wantLogger: func() *log.Logger {
w, err := SysEventer().StandardWriter(testCtx, ErrorType)
require.NoError(t, err)
return log.New(w, "okay", 0)
}(),
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
assert, require := assert.New(t), require.New(t)
e := SysEventer()
require.NotNil(e)
l, err := tt.eventer.StandardLogger(tt.ctx, tt.name, tt.eventType)
if tt.wantErr {
require.Error(err)
assert.Nil(l)
if tt.wantErrIs != nil {
assert.ErrorIs(err, tt.wantErrIs)
}
if tt.wantErrContains != "" {
assert.Contains(err.Error(), tt.wantErrContains)
}
return
}
require.NoError(err)
assert.NotNil(l)
assert.Equal(tt.wantLogger, l)
})
}
}
func Test_StandardWriter(t *testing.T) {
// this test and its subtests cannot be run in parallel because of it's
// dependency on the sysEventer
c := TestEventerConfig(t, "Test_StandardLogger")
testLock := &sync.Mutex{}
testLogger := hclog.New(&hclog.LoggerOptions{
Mutex: testLock,
Name: "test",
})
require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
testCtx, err := NewEventerContext(context.Background(), SysEventer())
require.NoError(t, err)
tests := []struct {
name string
eventer *Eventer
ctx context.Context
eventType Type
wantErr bool
wantErrIs error
wantErrContains string
wantWriter io.Writer
}{
{
name: "missing-eventer",
ctx: testCtx,
eventType: ErrorType,
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "nil eventer",
},
{
name: "missing-ctx",
eventer: SysEventer(),
eventType: ErrorType,
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "missing context",
},
{
name: "missing-type",
ctx: testCtx,
eventer: SysEventer(),
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "missing type",
},
{
name: "invalid-type",
ctx: testCtx,
eventer: SysEventer(),
eventType: "invalid",
wantErr: true,
wantErrIs: ErrInvalidParameter,
wantErrContains: "'invalid' is not a valid event type",
},
{
name: "okay",
ctx: context.Background(),
eventer: SysEventer(),
eventType: ErrorType,
wantWriter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
emitEventType: ErrorType,
},
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
assert, require := assert.New(t), require.New(t)
e := SysEventer()
require.NotNil(e)
l, err := tt.eventer.StandardWriter(tt.ctx, tt.eventType)
if tt.wantErr {
require.Error(err)
assert.Nil(l)
if tt.wantErrIs != nil {
assert.ErrorIs(err, tt.wantErrIs)
}
if tt.wantErrContains != "" {
assert.Contains(err.Error(), tt.wantErrContains)
}
return
}
require.NoError(err)
assert.NotNil(l)
assert.Equal(tt.wantWriter, l)
})
}
}
func Test_logAdapter_Write(t *testing.T) {
// this test and its subtests cannot be run in parallel because of it's
// dependency on the sysEventer
c := TestEventerConfig(t, "Test_StandardLogger")
testLock := &sync.Mutex{}
testLogger := hclog.New(&hclog.LoggerOptions{
Mutex: testLock,
Name: "test",
})
require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig)))
testCtx, err := NewEventerContext(context.Background(), SysEventer())
require.NoError(t, err)
tests := []struct {
name string
adapter *logAdapter
data []byte
wantErr bool
wantIsError error
wantErrContains string
wantErrorEvent string
wantSystemEvent string
}{
{
name: "nil-adapter",
data: []byte("nil-adapter"),
wantErr: true,
wantIsError: ErrInvalidParameter,
wantErrContains: "nil log adapter",
},
{
name: "emit-sys-event",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
emitEventType: SystemType,
},
data: []byte("emit-sys-event"),
wantSystemEvent: "emit-sys-event",
},
{
name: "pick-type-DEBUG",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[DEBUG] pick-type-DEBUG"),
wantSystemEvent: "pick-type-DEBUG",
},
{
name: "pick-type-TRACE",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[TRACE] pick-type-TRACE"),
wantSystemEvent: "pick-type-TRACE",
},
{
name: "pick-type-INFO",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[INFO] pick-type-INFO"),
wantSystemEvent: "pick-type-INFO",
},
{
name: "pick-type-WARN",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[WARN] pick-type-WARN"),
wantSystemEvent: "pick-type-WARN",
},
{
name: "emit-error-event",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
emitEventType: ErrorType,
},
data: []byte("emit-error-event"),
wantErrorEvent: "emit-error-event",
},
{
name: "pick-type-ERR",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[ERR] pick-type-ERR"),
wantErrorEvent: "pick-type-ERR",
},
{
name: "pick-type-ERROR",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
},
data: []byte("[ERROR] pick-type-ERROR"),
wantErrorEvent: "pick-type-ERROR",
},
{
name: "emit-every-type-event",
adapter: &logAdapter{
ctxWithEventer: testCtx,
e: SysEventer(),
emitEventType: EveryType,
},
data: []byte("emit-every-type-event"),
wantSystemEvent: "emit-every-type-event",
},
}
for _, tt := range tests {
t.Run(tt.name, func(t *testing.T) {
assert, require := assert.New(t), require.New(t)
i, err := tt.adapter.Write(tt.data)
if tt.wantErr {
require.Error(err)
assert.Zero(i)
if tt.wantIsError != nil {
assert.ErrorIs(err, tt.wantIsError)
}
if tt.wantErrContains != "" {
assert.Contains(err.Error(), tt.wantErrContains)
}
return
}
require.NoError(err)
assert.Equal(len(tt.data), i)
sinkFileName := c.AllEvents.Name()
defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }()
b, err := ioutil.ReadFile(sinkFileName)
require.NoError(err)
gotEvent := &cloudevents.Event{}
err = json.Unmarshal(b, gotEvent)
require.NoErrorf(err, "json: %s", string(b))
if tt.wantErrorEvent != "" {
gotData := gotEvent.Data.(map[string]interface{})
t.Log(tt.name, gotData)
assert.Equal(tt.wantErrorEvent, gotData["error"])
}
if tt.wantSystemEvent != "" {
gotData := gotEvent.Data.(map[string]interface{})["data"].(map[string]interface{})
t.Log(tt.name, gotData)
assert.Equal(tt.wantSystemEvent, gotData["msg"])
}
})
}
}

@ -12,12 +12,22 @@ import (
"time"
"github.com/hashicorp/boundary/internal/libs/alpnmux"
"github.com/hashicorp/boundary/internal/observability/event"
"github.com/hashicorp/go-multierror"
)
func (w *Worker) startListeners() error {
const op = "worker.(Worker).startListeners"
ctx := context.TODO()
servers := make([]func(), 0, len(w.conf.Listeners))
e := event.SysEventer()
if e == nil {
return fmt.Errorf("%s: sys eventer not initialized", op)
}
logger, err := e.StandardLogger(ctx, "listeners", event.ErrorType)
if err != nil {
return fmt.Errorf("%s: unable to initialize std logger: %w", op, err)
}
for _, ln := range w.conf.Listeners {
for _, purpose := range ln.Config.Purpose {
switch purpose {
@ -42,7 +52,7 @@ func (w *Worker) startListeners() error {
Handler: handler,
ReadHeaderTimeout: 10 * time.Second,
ReadTimeout: 30 * time.Second,
ErrorLog: w.logger.StandardLogger(nil),
ErrorLog: logger,
BaseContext: func(net.Listener) context.Context {
return cancelCtx
},

Loading…
Cancel
Save