event_logs: instrument SOAP-related event logs (#44325)

Author: unknwon

cmd/frontend/auth/user.go

@@ -5,9 +5,10 @@ import (
 	"encoding/json"
 	"fmt"
 
-	"github.com/inconshreveable/log15"
+	sglog "github.com/sourcegraph/log"
 
 	"github.com/sourcegraph/sourcegraph/internal/actor"
+	"github.com/sourcegraph/sourcegraph/internal/auth"
 	"github.com/sourcegraph/sourcegraph/internal/authz"
 	"github.com/sourcegraph/sourcegraph/internal/database"
 	"github.com/sourcegraph/sourcegraph/internal/deviceid"
@@ -62,14 +63,15 @@ func GetAndSaveUser(ctx context.Context, db database.DB, op GetAndSaveUserOp) (u
 		return MockGetAndSaveUser(ctx, op)
 	}
 
-	extacc := db.UserExternalAccounts()
+	externalAccountsStore := db.UserExternalAccounts()
+	logger := sglog.Scoped("authGetAndSaveUser", "get and save user authenticated by external providers")
 
 	userID, userSaved, extAcctSaved, safeErrMsg, err := func() (int32, bool, bool, string, error) {
 		if actor := actor.FromContext(ctx); actor.IsAuthenticated() {
 			return actor.UID, false, false, "", nil
 		}
 
-		uid, lookupByExternalErr := extacc.LookupUserAndSave(ctx, op.ExternalAccount, op.ExternalAccountData)
+		uid, lookupByExternalErr := externalAccountsStore.LookupUserAndSave(ctx, op.ExternalAccount, op.ExternalAccountData)
 		if lookupByExternalErr == nil {
 			return uid, false, true, "", nil
 		}
@@ -104,8 +106,18 @@ func GetAndSaveUser(ctx context.Context, db database.DB, op GetAndSaveUserOp) (u
 			return 0, false, false, "It looks like this is your first time signing in with this external identity. Sourcegraph couldn't link it to an existing user, because no verified email was provided. Ask your site admin to configure the auth provider to include the user's verified email on sign-in.", lookupByExternalErr
 		}
 
-		// If CreateIfNotExist is true, create the new user, regardless of whether the email was verified or not.
-		userID, err := extacc.CreateUserAndSave(ctx, op.UserProps, op.ExternalAccount, op.ExternalAccountData)
+		act := &actor.Actor{
+			SourcegraphOperator: op.ExternalAccount.ServiceType == auth.SourcegraphOperatorProviderType,
+		}
+
+		// If CreateIfNotExist is true, create the new user, regardless of whether the
+		// email was verified or not.
+		//
+		// NOTE: It is important to propagate the correct context that carries the
+		// information of the actor, especially whether the actor is a Sourcegraph
+		// operator or not.
+		ctx = actor.WithActor(ctx, act)
+		userID, err := externalAccountsStore.CreateUserAndSave(ctx, op.UserProps, op.ExternalAccount, op.ExternalAccountData)
 		switch {
 		case database.IsUsernameExists(err):
 			return 0, false, false, fmt.Sprintf("Username %q already exists, but no verified email matched %q", op.UserProps.Username, op.UserProps.Email), err
@@ -114,26 +126,68 @@ func GetAndSaveUser(ctx context.Context, db database.DB, op GetAndSaveUserOp) (u
 		case err != nil:
 			return 0, false, false, "Unable to create a new user account due to a unexpected error. Ask a site admin for help.", err
 		}
+		act.UID = userID
 
 		if err = db.Authz().GrantPendingPermissions(ctx, &database.GrantPendingPermissionsArgs{
 			UserID: userID,
 			Perm:   authz.Read,
 			Type:   authz.PermRepos,
 		}); err != nil {
-			log15.Error("Failed to grant user pending permissions", "userID", userID, "error", err)
+			logger.Error(
+				"failed to grant user pending permissions",
+				sglog.Int32("userID", userID),
+				sglog.Error(err),
+			)
+			// OK to continue, since this is a best-effort to improve the UX with some initial permissions available.
 		}
 
-		serviceTypeArg := json.RawMessage(fmt.Sprintf(`{"serviceType": %q}`, op.ExternalAccount.ServiceType))
-		if logErr := usagestats.LogBackendEvent(db, actor.FromContext(ctx).UID, deviceid.FromContext(ctx), "ExternalAuthSignupSucceeded", serviceTypeArg, serviceTypeArg, featureflag.GetEvaluatedFlagSet(ctx), nil); logErr != nil {
-			log15.Warn("Failed to log event ExternalAuthSignupSucceded", "error", logErr)
+		const eventName = "ExternalAuthSignupSucceeded"
+		args, err := json.Marshal(map[string]any{
+			// NOTE: The conventional name should be "service_type", but keeping as-is for
+			// backwards capability.
+			"serviceType": op.ExternalAccount.ServiceType,
+		})
+		if err != nil {
+			logger.Error(
+				"failed to marshal JSON for event log argument",
+				sglog.String("eventName", eventName),
+				sglog.Error(err),
+			)
+			// OK to continue, we still want the event log to be created
+		}
+
+		// NOTE: It is important to propagate the correct context that carries the
+		// information of the actor, especially whether the actor is a Sourcegraph
+		// operator or not.
+		err = usagestats.LogEvent(
+			ctx,
+			db,
+			usagestats.Event{
+				EventName: eventName,
+				UserID:    act.UID,
+				Argument:  args,
+				Source:    "BACKEND",
+			},
+		)
+		if err != nil {
+			logger.Error(
+				"failed to log event",
+				sglog.String("eventName", eventName),
+				sglog.Error(err),
+			)
 		}
 
 		return userID, true, true, "", nil
 	}()
 	if err != nil {
+		const eventName = "ExternalAuthSignupFailed"
 		serviceTypeArg := json.RawMessage(fmt.Sprintf(`{"serviceType": %q}`, op.ExternalAccount.ServiceType))
-		if logErr := usagestats.LogBackendEvent(db, actor.FromContext(ctx).UID, deviceid.FromContext(ctx), "ExternalAuthSignupFailed", serviceTypeArg, serviceTypeArg, featureflag.GetEvaluatedFlagSet(ctx), nil); logErr != nil {
-			log15.Warn("Failed to log event ExternalAuthSignUpFailed", "error", logErr)
+		if logErr := usagestats.LogBackendEvent(db, actor.FromContext(ctx).UID, deviceid.FromContext(ctx), eventName, serviceTypeArg, serviceTypeArg, featureflag.GetEvaluatedFlagSet(ctx), nil); logErr != nil {
+			logger.Error(
+				"failed to log event",
+				sglog.String("eventName", eventName),
+				sglog.Error(err),
+			)
 		}
 		return 0, safeErrMsg, err
 	}
@@ -162,7 +216,7 @@ func GetAndSaveUser(ctx context.Context, db database.DB, op GetAndSaveUserOp) (u
 
 	// Create/update the external account and ensure it's associated with the user ID
 	if !extAcctSaved {
-		err := extacc.AssociateUserAndSave(ctx, userID, op.ExternalAccount, op.ExternalAccountData)
+		err := externalAccountsStore.AssociateUserAndSave(ctx, userID, op.ExternalAccount, op.ExternalAccountData)
 		if err != nil {
 			return 0, "Unexpected error associating the external account with your Sourcegraph user. The most likely cause for this problem is that another Sourcegraph user is already linked with this external account. A site admin or the other user can unlink the account to fix this problem.", err
 		}
@@ -172,7 +226,12 @@ func GetAndSaveUser(ctx context.Context, db database.DB, op GetAndSaveUserOp) (u
 			Perm:   authz.Read,
 			Type:   authz.PermRepos,
 		}); err != nil {
-			log15.Error("Failed to grant user pending permissions", "userID", userID, "error", err)
+			logger.Error(
+				"failed to grant user pending permissions",
+				sglog.Int32("userID", userID),
+				sglog.Error(err),
+			)
+			// OK to continue, since this is a best-effort to improve the UX with some initial permissions available.
 		}
 	}
 

cmd/frontend/auth/user_test.go

@@ -7,9 +7,12 @@ import (
 	"testing"
 
 	"github.com/davecgh/go-spew/spew"
+	mockrequire "github.com/derision-test/go-mockgen/testutil/require"
 	"github.com/sergi/go-diff/diffmatchpatch"
+	"github.com/stretchr/testify/require"
 
 	"github.com/sourcegraph/sourcegraph/internal/actor"
+	"github.com/sourcegraph/sourcegraph/internal/auth"
 	"github.com/sourcegraph/sourcegraph/internal/database"
 	"github.com/sourcegraph/sourcegraph/internal/errcode"
 	"github.com/sourcegraph/sourcegraph/internal/extsvc"
@@ -419,6 +422,49 @@ func TestGetAndSaveUser(t *testing.T) {
 			}
 		})
 	}
+
+	t.Run("Sourcegraph operator actor should be propagated", func(t *testing.T) {
+		ctx := context.Background()
+
+		errNotFound := &errcode.Mock{
+			IsNotFound: true,
+		}
+		usersStore := database.NewMockUserStore()
+		usersStore.GetByVerifiedEmailFunc.SetDefaultReturn(nil, errNotFound)
+		externalAccountsStore := database.NewMockUserExternalAccountsStore()
+		externalAccountsStore.LookupUserAndSaveFunc.SetDefaultReturn(0, errNotFound)
+		externalAccountsStore.CreateUserAndSaveFunc.SetDefaultHook(func(ctx context.Context, _ database.NewUser, _ extsvc.AccountSpec, _ extsvc.AccountData) (int32, error) {
+			require.True(t, actor.FromContext(ctx).SourcegraphOperator, "the actor should be a Sourcegraph operator")
+			return 1, nil
+		})
+		eventLogsStore := database.NewMockEventLogStore()
+		eventLogsStore.BulkInsertFunc.SetDefaultHook(func(ctx context.Context, _ []*database.Event) error {
+			require.True(t, actor.FromContext(ctx).SourcegraphOperator, "the actor should be a Sourcegraph operator")
+			return nil
+		})
+		db := database.NewMockDB()
+		db.UsersFunc.SetDefaultReturn(usersStore)
+		db.UserExternalAccountsFunc.SetDefaultReturn(externalAccountsStore)
+		db.AuthzFunc.SetDefaultReturn(database.NewMockAuthzStore())
+		db.EventLogsFunc.SetDefaultReturn(eventLogsStore)
+
+		_, _, err := GetAndSaveUser(
+			ctx,
+			db,
+			GetAndSaveUserOp{
+				UserProps: database.NewUser{
+					EmailIsVerified: true,
+				},
+				ExternalAccount: extsvc.AccountSpec{
+					ServiceType: auth.SourcegraphOperatorProviderType,
+				},
+				ExternalAccountData: extsvc.AccountData{},
+				CreateIfNotExist:    true,
+			},
+		)
+		require.NoError(t, err)
+		mockrequire.Called(t, externalAccountsStore.CreateUserAndSaveFunc)
+	})
 }
 
 type userInfo struct {

cmd/frontend/graphqlbackend/graphqlbackend.go

@@ -32,6 +32,7 @@ import (
 	sgtrace "github.com/sourcegraph/sourcegraph/internal/trace"
 	"github.com/sourcegraph/sourcegraph/internal/trace/policy"
 	"github.com/sourcegraph/sourcegraph/internal/types"
+	"github.com/sourcegraph/sourcegraph/internal/usagestats"
 	"github.com/sourcegraph/sourcegraph/lib/errors"
 )
 
@@ -43,11 +44,13 @@ var (
 	}, []string{"type", "field", "error", "source", "request_name"})
 )
 
-type prometheusTracer struct {
+type requestTracer struct {
+	DB     database.DB
 	tracer trace.OpenTracingTracer
+	logger sglog.Logger
 }
 
-func (t *prometheusTracer) TraceQuery(ctx context.Context, queryString string, operationName string, variables map[string]any, varTypes map[string]*introspection.Type) (context.Context, trace.TraceQueryFinishFunc) {
+func (t *requestTracer) TraceQuery(ctx context.Context, queryString string, operationName string, variables map[string]any, varTypes map[string]*introspection.Type) (context.Context, trace.TraceQueryFinishFunc) {
 	start := time.Now()
 	var finish trace.TraceQueryFinishFunc
 	if policy.ShouldTrace(ctx) {
@@ -64,6 +67,48 @@ func (t *prometheusTracer) TraceQuery(ctx context.Context, queryString string, o
 		currentUserID = a.UID
 	}
 
+	// 🚨 SECURITY: We want to log every single operation the Sourcegraph operator
+	// has done on the instance, so we need to do additional logging here. Sometimes
+	// we would end up having logging twice for the same operation (here and the web
+	// app), but we would not want to risk missing logging operations. Also in the
+	// future, we expect audit logging of Sourcegraph operators to live outside the
+	// instance, which makes this pattern less of a concern in terms of redundancy.
+	if a.SourcegraphOperator {
+		const eventName = "SourcegraphOperatorGraphQLRequest"
+		args, err := json.Marshal(map[string]any{
+			"queryString": queryString,
+			"variables":   variables,
+		})
+		if err != nil {
+			t.logger.Error(
+				"failed to marshal JSON for event log argument",
+				sglog.String("eventName", eventName),
+				sglog.Error(err),
+			)
+		}
+
+		// NOTE: It is important to propagate the correct context that carries the
+		// information of the actor, especially whether the actor is a Sourcegraph
+		// operator or not.
+		err = usagestats.LogEvent(
+			ctx,
+			t.DB,
+			usagestats.Event{
+				EventName: eventName,
+				UserID:    a.UID,
+				Argument:  args,
+				Source:    "BACKEND",
+			},
+		)
+		if err != nil {
+			t.logger.Error(
+				"failed to log event",
+				sglog.String("eventName", eventName),
+				sglog.Error(err),
+			)
+		}
+	}
+
 	// Requests made by our JS frontend and other internal things will have a concrete name attached to the
 	// request which allows us to (softly) differentiate it from end-user API requests. For example,
 	// /.api/graphql?Foobar where Foobar is the name of the request we make. If there is not a request name,
@@ -96,7 +141,7 @@ VARIABLES
 	}
 }
 
-func (prometheusTracer) TraceField(ctx context.Context, label, typeName, fieldName string, trivial bool, args map[string]any) (context.Context, trace.TraceFieldFinishFunc) {
+func (requestTracer) TraceField(ctx context.Context, label, typeName, fieldName string, trivial bool, args map[string]any) (context.Context, trace.TraceFieldFinishFunc) {
 	// We don't call into t.OpenTracingTracer.TraceField since it generates too many spans which is really hard to read.
 	start := time.Now()
 	return ctx, func(err *gqlerrors.QueryError) {
@@ -111,7 +156,7 @@ func (prometheusTracer) TraceField(ctx context.Context, label, typeName, fieldNa
 	}
 }
 
-func (t prometheusTracer) TraceValidation(ctx context.Context) trace.TraceValidationFinishFunc {
+func (t requestTracer) TraceValidation(ctx context.Context) trace.TraceValidationFinishFunc {
 	var finish trace.TraceValidationFinishFunc
 	if policy.ShouldTrace(ctx) {
 		finish = t.tracer.TraceValidation(ctx)
@@ -461,10 +506,14 @@ func NewSchema(
 		}
 	}
 
+	logger := sglog.Scoped("GraphQL", "general GraphQL logging")
 	return graphql.ParseSchema(
 		strings.Join(schemas, "\n"),
 		resolver,
-		graphql.Tracer(&prometheusTracer{}),
+		graphql.Tracer(&requestTracer{
+			DB:     db,
+			logger: logger,
+		}),
 		graphql.UseStringDescriptions(),
 	)
 }

cmd/frontend/graphqlbackend/search_test.go

@@ -117,7 +117,7 @@ func TestSearch(t *testing.T) {
 			gsClient.ResolveRevisionFunc.SetDefaultHook(tc.repoRevsMock)
 
 			sr := newSchemaResolver(db, gsClient)
-			schema, err := graphql.ParseSchema(mainSchema, sr, graphql.Tracer(&prometheusTracer{}))
+			schema, err := graphql.ParseSchema(mainSchema, sr, graphql.Tracer(&requestTracer{}))
 			if err != nil {
 				t.Fatal(err)
 			}

cmd/frontend/internal/cli/http.go

@@ -63,7 +63,7 @@ func newExternalHTTPHandler(
 	// 🚨 SECURITY: The HTTP API should not accept cookies as authentication, except from trusted
 	// origins, to avoid CSRF attacks. See session.CookieMiddlewareWithCSRFSafety for details.
 	apiHandler = session.CookieMiddlewareWithCSRFSafety(logger, db, apiHandler, corsAllowHeader, isTrustedOrigin) // API accepts cookies with special header
-	apiHandler = internalhttpapi.AccessTokenAuthMiddleware(db, apiHandler)                                        // API accepts access tokens
+	apiHandler = internalhttpapi.AccessTokenAuthMiddleware(db, logger, apiHandler)                                // API accepts access tokens
 	apiHandler = requestclient.HTTPMiddleware(apiHandler)
 	apiHandler = gziphandler.GzipHandler(apiHandler)
 	if envvar.SourcegraphDotComMode() {
@@ -85,8 +85,8 @@ func newExternalHTTPHandler(
 	appHandler = actor.AnonymousUIDMiddleware(appHandler)
 	appHandler = authMiddlewares.App(appHandler) // 🚨 SECURITY: auth middleware
 	appHandler = middleware.OpenGraphMetadataMiddleware(db.FeatureFlags(), appHandler)
-	appHandler = session.CookieMiddleware(logger, db, appHandler)          // app accepts cookies
-	appHandler = internalhttpapi.AccessTokenAuthMiddleware(db, appHandler) // app accepts access tokens
+	appHandler = session.CookieMiddleware(logger, db, appHandler)                  // app accepts cookies
+	appHandler = internalhttpapi.AccessTokenAuthMiddleware(db, logger, appHandler) // app accepts access tokens
 	appHandler = requestclient.HTTPMiddleware(appHandler)
 	if envvar.SourcegraphDotComMode() {
 		appHandler = deviceid.Middleware(appHandler)