feature (events): Classify auth method request/resp messages for audit events. (#1640)

* refactor (oidc): Stop emitting error for not found token id

Stop emitting errors when authtoken repo.IssueAuthToken is called and
there's if no pending token.  It's not an "normal" state and not
an error condition.

* feature (audit tagging): Add tags for auth method requests/responses

Including testing functions for asserting audit events created
when a service is called

internal/tests/api/authmethods/authenticate_test.go

@@ -4,19 +4,41 @@ import (
 	"encoding/json"
 	"fmt"
 	"net/http"
+	"os"
+	"sync"
 	"testing"
 
 	"github.com/hashicorp/boundary/api"
 	"github.com/hashicorp/boundary/api/authmethods"
 	"github.com/hashicorp/boundary/api/authtokens"
+	"github.com/hashicorp/boundary/internal/cmd/config"
+	"github.com/hashicorp/boundary/internal/observability/event"
 	"github.com/hashicorp/boundary/internal/servers/controller"
+	tests_api "github.com/hashicorp/boundary/internal/tests/api"
+	"github.com/hashicorp/go-hclog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
+// TestAuthenticate tests the api calls and the audit events it should produce
 func TestAuthenticate(t *testing.T) {
+	// this cannot run in parallel because it relies on envvar
+	// globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS
+	event.TestEnableEventing(t, true)
+
 	assert, require := assert.New(t), require.New(t)
-	tc := controller.NewTestController(t, nil)
+	eventConfig := event.TestEventerConfig(t, "TestAuthenticateAuditEntry", event.TestWithAuditSink(t))
+	testLock := &sync.Mutex{}
+	testLogger := hclog.New(&hclog.LoggerOptions{
+		Mutex: testLock,
+		Name:  "test",
+	})
+	require.NoError(event.InitSysEventer(testLogger, testLock, "TestAuthenticateAuditEntry", event.WithEventerConfig(&eventConfig.EventerConfig)))
+	tcConfig, err := config.DevController()
+	require.NoError(err)
+	tcConfig.Eventing = &eventConfig.EventerConfig
+
+	tc := controller.NewTestController(t, &controller.TestControllerOpts{Config: tcConfig})
 	defer tc.Shutdown()
 
 	client := tc.Client()
@@ -49,4 +71,30 @@ func TestAuthenticate(t *testing.T) {
 	token := new(authtokens.AuthToken)
 	require.NoError(json.Unmarshal(result.GetRawAttributes(), token))
 	require.NotEmpty(token.Token)
+
+	require.NotNil(eventConfig.AuditEvents)
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
+
+	tok, err = methods.Authenticate(tc.Context(), tc.Server().DevPasswordAuthMethodId, "login", map[string]interface{}{"login_name": "user", "password": "passpass"})
+	require.NoError(err)
+	assert.NotNil(tok)
+	got := tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+
+	reqDetails := tests_api.GetEventDetails(t, got, "request")
+	tests_api.AssertRedactedValues(t, reqDetails)
+	tests_api.AssertRedactedValues(t, reqDetails["attributes"], "password")
+
+	respDetails := tests_api.GetEventDetails(t, got, "response")
+	tests_api.AssertRedactedValues(t, respDetails)
+	tests_api.AssertRedactedValues(t, respDetails["attributes"], "token")
+
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
+	tok, err = methods.Authenticate(tc.Context(), tc.Server().DevPasswordAuthMethodId, "login", map[string]interface{}{"login_name": "user", "password": "bad-pass"})
+	require.Error(err)
+	assert.Nil(tok)
+	got = tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+
+	reqDetails = tests_api.GetEventDetails(t, got, "request")
+	tests_api.AssertRedactedValues(t, reqDetails)
+	tests_api.AssertRedactedValues(t, reqDetails["attributes"], "password")
 }

internal/tests/api/authmethods/authmethod_test.go

@@ -2,13 +2,19 @@ package authmethods_test
 
 import (
 	"net/http"
+	"os"
+	"sync"
 	"testing"
 
 	"github.com/hashicorp/boundary/api"
 	"github.com/hashicorp/boundary/api/authmethods"
 	"github.com/hashicorp/boundary/internal/auth/password"
+	"github.com/hashicorp/boundary/internal/cmd/config"
+	"github.com/hashicorp/boundary/internal/observability/event"
 	"github.com/hashicorp/boundary/internal/servers/controller"
+	tests_api "github.com/hashicorp/boundary/internal/tests/api"
 	capoidc "github.com/hashicorp/cap/oidc"
+	"github.com/hashicorp/go-hclog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -16,8 +22,23 @@ import (
 const global = "global"
 
 func TestCrud(t *testing.T) {
+	// this cannot run in parallel because it relies on envvar
+	// globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS
+	event.TestEnableEventing(t, true)
+
 	assert, require := assert.New(t), require.New(t)
-	tc := controller.NewTestController(t, nil)
+	eventConfig := event.TestEventerConfig(t, "TestCrud", event.TestWithAuditSink(t))
+	testLock := &sync.Mutex{}
+	testLogger := hclog.New(&hclog.LoggerOptions{
+		Mutex: testLock,
+		Name:  "test",
+	})
+	require.NoError(event.InitSysEventer(testLogger, testLock, "TestCrud", event.WithEventerConfig(&eventConfig.EventerConfig)))
+	tcConfig, err := config.DevController()
+	require.NoError(err)
+	tcConfig.Eventing = &eventConfig.EventerConfig
+
+	tc := controller.NewTestController(t, &controller.TestControllerOpts{Config: tcConfig})
 	defer tc.Shutdown()
 
 	client := tc.Client()
@@ -35,18 +56,44 @@ func TestCrud(t *testing.T) {
 		assert.EqualValues(wantedVersion, u.Version)
 	}
 
+	require.NotNil(eventConfig.AuditEvents)
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
 	u, err := amClient.Create(tc.Context(), "password", global,
 		authmethods.WithName("bar"))
 	require.NoError(err)
 	checkAuthMethod("create", u.Item, "bar", 1)
 
+	got := tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+	reqItem := tests_api.GetEventDetails(t, got, "request")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, reqItem)
+
+	respItem := tests_api.GetEventDetails(t, got, "response")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, respItem)
+	tests_api.AssertRedactedValues(t, respItem["attributes"])
+
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
 	u, err = amClient.Read(tc.Context(), u.Item.Id)
 	require.NoError(err)
 	checkAuthMethod("read", u.Item, "bar", 1)
 
+	got = tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+	tests_api.AssertRedactedValues(t, tests_api.GetEventDetails(t, got, "request"))
+
+	respItem = tests_api.GetEventDetails(t, got, "response")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, respItem)
+	tests_api.AssertRedactedValues(t, respItem["attributes"])
+
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
 	u, err = amClient.Update(tc.Context(), u.Item.Id, u.Item.Version, authmethods.WithName("buz"))
 	require.NoError(err)
 	checkAuthMethod("update", u.Item, "buz", 2)
+	got = tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+
+	tests_api.AssertRedactedValues(t, tests_api.GetEventDetails(t, got, "request")["item"].(map[string]interface{}))
+
+	respItem = tests_api.GetEventDetails(t, got, "response")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, respItem)
+	tests_api.AssertRedactedValues(t, respItem["attributes"])
 
 	u, err = amClient.Update(tc.Context(), u.Item.Id, u.Item.Version, authmethods.DefaultName())
 	require.NoError(err)
@@ -55,6 +102,7 @@ func TestCrud(t *testing.T) {
 	_, err = amClient.Delete(tc.Context(), u.Item.Id)
 	require.NoError(err)
 
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
 	// OIDC auth methods
 	u, err = amClient.Create(tc.Context(), "oidc", global,
 		authmethods.WithName("foo"),
@@ -64,6 +112,15 @@ func TestCrud(t *testing.T) {
 		authmethods.WithOidcAuthMethodClientId("client-id"))
 	require.NoError(err)
 	checkAuthMethod("create", u.Item, "foo", 1)
+	got = tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+
+	reqItem = tests_api.GetEventDetails(t, got, "request")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, reqItem)
+	tests_api.AssertRedactedValues(t, reqItem["attributes"], "client_secret")
+
+	respItem = tests_api.GetEventDetails(t, got, "response")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, respItem)
+	tests_api.AssertRedactedValues(t, respItem["attributes"])
 
 	u, err = amClient.Read(tc.Context(), u.Item.Id)
 	require.NoError(err)
@@ -82,7 +139,23 @@ func TestCrud(t *testing.T) {
 }
 
 func TestCustomMethods(t *testing.T) {
-	tc := controller.NewTestController(t, nil)
+	// this cannot run in parallel because it relies on envvar
+	// globals.BOUNDARY_DEVELOPER_ENABLE_EVENTS
+	event.TestEnableEventing(t, true)
+
+	assert, require := assert.New(t), require.New(t)
+	eventConfig := event.TestEventerConfig(t, "TestCrud", event.TestWithAuditSink(t))
+	testLock := &sync.Mutex{}
+	testLogger := hclog.New(&hclog.LoggerOptions{
+		Mutex: testLock,
+		Name:  "test",
+	})
+	require.NoError(event.InitSysEventer(testLogger, testLock, "TestCrud", event.WithEventerConfig(&eventConfig.EventerConfig)))
+	tcConfig, err := config.DevController()
+	require.NoError(err)
+	tcConfig.Eventing = &eventConfig.EventerConfig
+
+	tc := controller.NewTestController(t, &controller.TestControllerOpts{Config: tcConfig})
 	defer tc.Shutdown()
 
 	client := tc.Client()
@@ -104,20 +177,30 @@ func TestCustomMethods(t *testing.T) {
 		authmethods.WithOidcAuthMethodClientId("client-id"),
 		authmethods.WithOidcAuthMethodSigningAlgorithms([]string{string("EdDSA")}),
 		authmethods.WithOidcAuthMethodIdpCaCerts([]string{tp.CACert()}))
-	require.NoError(t, err)
+	require.NoError(err)
 
 	const newState = "active-private"
 	nilU, err := amClient.ChangeState(tc.Context(), u.Item.Id, u.Item.Version, newState)
-	require.Error(t, err)
-	assert.Nil(t, nilU)
+	require.Error(err)
+	assert.Nil(nilU)
 
+	_ = os.WriteFile(eventConfig.AuditEvents.Name(), nil, 0o666) // clean out audit events from previous calls
 	u, err = amClient.ChangeState(tc.Context(), u.Item.Id, u.Item.Version, newState, authmethods.WithOidcAuthMethodDisableDiscoveredConfigValidation(true))
-	require.NoError(t, err)
-	assert.NotNil(t, u)
-	assert.Equal(t, newState, u.Item.Attributes["state"])
+	require.NoError(err)
+	assert.NotNil(u)
+	assert.Equal(newState, u.Item.Attributes["state"])
+	got := tests_api.CloudEventFromFile(t, eventConfig.AuditEvents.Name())
+
+	reqDetails := tests_api.GetEventDetails(t, got, "request")
+	tests_api.AssertRedactedValues(t, reqDetails)
+	tests_api.AssertRedactedValues(t, reqDetails["attributes"])
+
+	respItem := tests_api.GetEventDetails(t, got, "response")["item"].(map[string]interface{})
+	tests_api.AssertRedactedValues(t, respItem)
+	tests_api.AssertRedactedValues(t, respItem["attributes"])
 
 	_, err = amClient.ChangeState(tc.Context(), u.Item.Id, u.Item.Version, "", authmethods.WithOidcAuthMethodDisableDiscoveredConfigValidation(true))
-	assert.Error(t, err)
+	assert.Error(err)
 }
 
 func TestErrors(t *testing.T) {

internal/tests/api/testing.go

@@ -0,0 +1,80 @@
+package api
+
+import (
+	"encoding/json"
+	"io/ioutil"
+	"testing"
+
+	"github.com/hashicorp/eventlogger/filters/encrypt"
+	"github.com/hashicorp/eventlogger/formatter_filters/cloudevents"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+// CloudEventFromFile will marshal a single cloud event from the provided file
+// name
+func CloudEventFromFile(t *testing.T, fileName string) *cloudevents.Event {
+	t.Helper()
+	b, err := ioutil.ReadFile(fileName)
+	assert.NoError(t, err)
+	got := &cloudevents.Event{}
+	err = json.Unmarshal(b, got)
+	require.NoErrorf(t, err, "json: %s", string(b))
+	return got
+}
+
+// GetEventDetails is a testing helper will return the details from the event
+// payload for a given messageType (request or response)
+func GetEventDetails(t *testing.T, e *cloudevents.Event, messageType string) map[string]interface{} {
+	t.Helper()
+	require := require.New(t)
+	require.NotNil(e)
+	require.NotEmpty(messageType)
+	data, ok := e.Data.(map[string]interface{})
+	if !ok {
+		return nil
+	}
+	msgType, ok := data[messageType].(map[string]interface{})
+	if !ok {
+		return nil
+	}
+
+	details, ok := msgType["details"].(map[string]interface{})
+	if !ok {
+		return nil
+	}
+	return details
+}
+
+// AssertRedactedValues will assert that the values for the given keys within
+// the data have been redacted
+func AssertRedactedValues(t *testing.T, data interface{}, keys ...string) {
+	t.Helper()
+	assert, require := assert.New(t), require.New(t)
+	require.NotNil(data)
+	dataMap, ok := data.(map[string]interface{})
+	require.Truef(ok, "data must be a map[string]interface{}")
+
+	rMap := make(map[string]bool, len(keys))
+	for _, s := range keys {
+		rMap[s] = true
+	}
+	for k, v := range dataMap {
+		switch typ := v.(type) {
+		case []interface{}:
+			for _, s := range typ {
+				if _, ok := rMap[k]; ok {
+					assert.Equalf(encrypt.RedactedData, s, "expected %s to be redacted and it was set to: %s", k, v)
+				} else {
+					assert.NotEqualf(encrypt.RedactedData, s, "did not expect %s to be redacted", k)
+				}
+			}
+		default:
+			if _, ok := rMap[k]; ok {
+				assert.Equalf(encrypt.RedactedData, v, "expected %s to be redacted and it was set to: %s", k, v)
+			} else {
+				assert.NotEqualf(encrypt.RedactedData, v, "did not expect %s to be redacted", k)
+			}
+		}
+	}
+}