fix(pam/integration-tests): Improve reliability of PAM integration te…

…sts and actually run them in race mode (#560)

Since we rely a lot on sleeping on the integration tests, due to the
fact we can't yet go with charmbracelet/vhs#257,
we need to be able to tune this value depending on the context we're
running the tests.

In general sanitizers slows down the runtime quite a bit (especially the
thread one), so make possible to use dynamic sleep times values
depending on variables that we adjust depending on the context we're
running in.
Tests can now slowed up/down using `AUTHD_TESTS_SLEEP_MULTIPLIER`
variable too (this can be used for helping local testing too, e.g.
personally I can reliably run the tests faster in my machine - with no
failures - using `AUTHD_TESTS_SLEEP_MULTIPLIER=0.3`; but also it helps
to quickly "fix" slower machines).

Tune the tape files so that we don't miss some changing contents (as in
the MFA/QrCode tests) and make the example broker to be a bit lazier.

Then, I noticed that we were not actually running the integration tests
in `-race` mode, so fix this. Indeed this implies slower tests, but at
least now we're fully checking for races both the daemon and the client.

This worked fine in various builds both in my fork and in a private repo
fork I did where the builders are way slower than the public ones.

UDENG-4793

.github/workflows/qa.yaml

@@ -217,6 +217,8 @@ jobs:
 
       - name: Run tests (with race detector)
         if: matrix.test == 'race'
+        env:
+          GO_TESTS_TIMEOUT: 35m
         run: |
           go test -timeout ${GO_TESTS_TIMEOUT} -race ./...
 
@@ -227,15 +229,22 @@ jobs:
           # stack trace information in case of ASAN errors.
           CGO_CFLAGS: "-O0 -g3 -fno-omit-frame-pointer"
           G_DEBUG: "fatal-criticals"
+          GO_TESTS_TIMEOUT: 30m
+          # Use these flags to give ASAN a better time to unwind the stack trace
+          GO_GC_FLAGS: -N -l
         run: |
-          # Use `-dwarflocationlists` to give ASAN a better time to unwind the stack trace
-          go test -C ./pam/internal -asan -gcflags="-dwarflocationlists=true" -timeout ${GO_TESTS_TIMEOUT} ./...
+          go test -C ./pam/internal -asan -gcflags=all="${GO_GC_FLAGS}" -timeout ${GO_TESTS_TIMEOUT} ./... || exit_code=$?
+          if [ "${exit_code}" -ne 0 ]; then
+            cat "${AUTHD_TEST_ARTIFACTS_PATH}"/asan.log* || true
+            exit ${exit_code}
+          fi
 
           pushd ./pam/integration-tests
-          go test -asan -gcflags="-dwarflocationlists=true" -timeout ${GO_TESTS_TIMEOUT} -c
+          go test -asan -gcflags=all="${GO_GC_FLAGS}" -c
           # FIXME: Suppression may be removed with newer libpam, as the one we ship in ubuntu as some leaks
           env LSAN_OPTIONS=suppressions=$(pwd)/lsan.supp \
             ./integration-tests.test \
+              -test.timeout ${GO_TESTS_TIMEOUT} \
             || exit_code=$?
           popd
 

examplebroker/broker.go

@@ -15,12 +15,16 @@ import (
 	"errors"
 	"fmt"
 	"html/template"
+	"math"
+	"os"
 	"sort"
+	"strconv"
 	"strings"
 	"sync"
 	"time"
 
 	"github.com/google/uuid"
+	"github.com/ubuntu/authd/internal/log"
 	"golang.org/x/exp/slices"
 )
 
@@ -80,6 +84,8 @@ type Broker struct {
 	isAuthenticatedCallsMu sync.Mutex
 
 	privateKey *rsa.PrivateKey
+
+	sleepMultiplier float64
 }
 
 type userInfoBroker struct {
@@ -112,6 +118,20 @@ func New(name string) (b *Broker, fullName, brandIcon string) {
 		panic(fmt.Sprintf("could not create an valid rsa key: %v", err))
 	}
 
+	sleepMultiplier := 1.0
+	if v := os.Getenv("AUTHD_EXAMPLE_BROKER_SLEEP_MULTIPLIER"); v != "" {
+		var err error
+		sleepMultiplier, err = strconv.ParseFloat(v, 64)
+		if err != nil {
+			panic(err)
+		}
+		if sleepMultiplier <= 0 {
+			panic("Negative or 0 sleep multiplier is not supported")
+		}
+	}
+
+	log.Debugf(context.TODO(), "Using sleep multiplier: %f", sleepMultiplier)
+
 	return &Broker{
 		currentSessions:        make(map[string]sessionInfo),
 		currentSessionsMu:      sync.RWMutex{},
@@ -120,6 +140,7 @@ func New(name string) (b *Broker, fullName, brandIcon string) {
 		isAuthenticatedCalls:   make(map[string]isAuthenticatedCtx),
 		isAuthenticatedCallsMu: sync.Mutex{},
 		privateKey:             privateKey,
+		sleepMultiplier:        sleepMultiplier,
 	}, strings.ReplaceAll(name, "_", " "), fmt.Sprintf("/usr/share/brokers/%s.png", name)
 }
 
@@ -523,7 +544,7 @@ func (b *Broker) IsAuthenticated(ctx context.Context, sessionID, authenticationD
 		b.isAuthenticatedCallsMu.Unlock()
 	}()
 
-	access, data, err = b.handleIsAuthenticated(ctx, sessionInfo, authData)
+	access, data = b.handleIsAuthenticated(ctx, sessionInfo, authData)
 	if access == AuthGranted && sessionInfo.currentAuthStep < sessionInfo.neededAuthSteps {
 		sessionInfo.currentAuthStep++
 		access = AuthNext
@@ -549,82 +570,93 @@ func (b *Broker) IsAuthenticated(ctx context.Context, sessionID, authenticationD
 	return access, data, err
 }
 
-func (b *Broker) handleIsAuthenticated(ctx context.Context, sessionInfo sessionInfo, authData map[string]string) (access, data string, err error) {
+func (b *Broker) sleepDuration(in time.Duration) time.Duration {
+	return time.Duration(math.Round(float64(in) * b.sleepMultiplier))
+}
+
+func (b *Broker) handleIsAuthenticated(ctx context.Context, sessionInfo sessionInfo, authData map[string]string) (access, data string) {
 	// Decrypt challenge if present.
 	challenge, err := decodeRawChallenge(b.privateKey, authData["challenge"])
 	if err != nil {
-		return AuthRetry, fmt.Sprintf(`{"message": "could not decode challenge: %v"}`, err), nil
+		return AuthRetry, fmt.Sprintf(`{"message": "could not decode challenge: %v"}`, err)
 	}
 
+	exampleUsersMu.Lock()
+	user, userExists := exampleUsers[sessionInfo.username]
+	exampleUsersMu.Unlock()
+	if !userExists {
+		return AuthDenied, `{"message": "user not found"}`
+	}
+
+	sleepDuration := b.sleepDuration(4 * time.Second)
+
 	// Note that the "wait" authentication can be cancelled and switch to another mode with a challenge.
 	// Take into account the cancellation.
 	switch sessionInfo.currentAuthMode {
 	case "password":
-		exampleUsersMu.RLock()
-		defer exampleUsersMu.RUnlock()
-		expectedChallenge := exampleUsers[sessionInfo.username].Password
+		expectedChallenge := user.Password
 
 		if challenge != expectedChallenge {
-			return AuthRetry, fmt.Sprintf(`{"message": "invalid password '%s', should be '%s'"}`, challenge, expectedChallenge), nil
+			return AuthRetry, fmt.Sprintf(`{"message": "invalid password '%s', should be '%s'"}`, challenge, expectedChallenge)
 		}
 
 	case "pincode":
 		if challenge != "4242" {
-			return AuthRetry, `{"message": "invalid pincode, should be 4242"}`, nil
+			return AuthRetry, `{"message": "invalid pincode, should be 4242"}`
 		}
 
 	case "totp_with_button", "totp":
 		wantedCode := sessionInfo.allModes[sessionInfo.currentAuthMode]["wantedCode"]
 		if challenge != wantedCode {
-			return AuthRetry, `{"message": "invalid totp code"}`, nil
+			return AuthRetry, `{"message": "invalid totp code"}`
 		}
 
 	case "phoneack1":
 		// TODO: should this be an error rather (not expected data from the PAM module?
 		if authData["wait"] != "true" {
-			return AuthDenied, `{"message": "phoneack1 should have wait set to true"}`, nil
+			return AuthDenied, `{"message": "phoneack1 should have wait set to true"}`
 		}
 		// Send notification to phone1 and wait on server signal to return if OK or not
 		select {
-		case <-time.After(2 * time.Second):
+		case <-time.After(sleepDuration):
 		case <-ctx.Done():
-			return AuthCancelled, "", nil
+			return AuthCancelled, ""
 		}
 
 	case "phoneack2":
 		if authData["wait"] != "true" {
-			return AuthDenied, `{"message": "phoneack2 should have wait set to true"}`, nil
+			return AuthDenied, `{"message": "phoneack2 should have wait set to true"}`
 		}
 
 		// This one is failing remotely as an example
 		select {
-		case <-time.After(2 * time.Second):
-			return AuthDenied, `{"message": "Timeout reached"}`, nil
+		case <-time.After(sleepDuration):
+			return AuthDenied, `{"message": "Timeout reached"}`
 		case <-ctx.Done():
-			return AuthCancelled, "", nil
+			return AuthCancelled, ""
 		}
 
 	case "fidodevice1":
 		if authData["wait"] != "true" {
-			return AuthDenied, `{"message": "fidodevice1 should have wait set to true"}`, nil
+			return AuthDenied, `{"message": "fidodevice1 should have wait set to true"}`
 		}
 
 		// simulate direct exchange with the FIDO device
 		select {
-		case <-time.After(2 * time.Second):
+		case <-time.After(sleepDuration):
 		case <-ctx.Done():
-			return AuthCancelled, "", nil
+			return AuthCancelled, ""
 		}
 
 	case "qrcodewithtypo", "qrcodeandcodewithtypo":
 		if authData["wait"] != "true" {
-			return AuthDenied, fmt.Sprintf(`{"message": "%s should have wait set to true"}`, sessionInfo.currentAuthMode), nil
+			return AuthDenied, fmt.Sprintf(`{"message": "%s should have wait set to true"}`, sessionInfo.currentAuthMode)
 		}
 		// Simulate connexion with remote server to check that the correct code was entered
 		select {
-		case <-time.After(2 * time.Second):
+		case <-time.After(sleepDuration):
 		case <-ctx.Done():
-			return AuthCancelled, "", nil
+			return AuthCancelled, ""
 		}
 
 	case "optionalreset":
@@ -633,20 +665,19 @@ func (b *Broker) handleIsAuthenticated(ctx context.Context, sessionInfo sessionI
 		}
 		fallthrough
 	case "mandatoryreset":
-		exampleUsersMu.Lock()
-		defer exampleUsersMu.Unlock()
-
 		expectedChallenge := "authd2404"
 		// Reset the password to default if it had already been changed.
 		// As at PAM level we'd refuse a previous password to be re-used.
-		if exampleUsers[sessionInfo.username].Password == expectedChallenge {
+		if user.Password == expectedChallenge {
 			expectedChallenge = "goodpass"
 		}
 
 		if challenge != expectedChallenge {
-			return AuthRetry, fmt.Sprintf(`{"message": "new password does not match criteria: must be '%s'"}`, expectedChallenge), nil
+			return AuthRetry, fmt.Sprintf(`{"message": "new password does not match criteria: must be '%s'"}`, expectedChallenge)
 		}
+		exampleUsersMu.Lock()
 		exampleUsers[sessionInfo.username] = userInfoBroker{Password: challenge}
+		exampleUsersMu.Unlock()
 	}
 
 	// this case name was dynamically generated
@@ -655,25 +686,22 @@ func (b *Broker) handleIsAuthenticated(ctx context.Context, sessionInfo sessionI
 		if challenge != "" {
 			// validate challenge given manually by the user
 			if challenge != "aaaaa" {
-				return AuthDenied, `{"message": "invalid challenge, should be aaaaa"}`, nil
+				return AuthDenied, `{"message": "invalid challenge, should be aaaaa"}`
 			}
 		} else if authData["wait"] == "true" {
 			// we are simulating clicking on the url signal received by the broker
 			// this can be cancelled to resend a challenge
 			select {
-			case <-time.After(10 * time.Second):
+			case <-time.After(b.sleepDuration(10 * time.Second)):
 			case <-ctx.Done():
-				return AuthCancelled, "", nil
+				return AuthCancelled, ""
 			}
 		} else {
-			return AuthDenied, `{"message": "challenge timeout "}`, nil
+			return AuthDenied, `{"message": "challenge timeout "}`
 		}
 	}
 
-	if _, exists := exampleUsers[sessionInfo.username]; !exists {
-		return AuthDenied, `{"message": "user not found"}`, nil
-	}
-	return AuthGranted, fmt.Sprintf(`{"userinfo": %s}`, userInfoFromName(sessionInfo.username)), nil
+	return AuthGranted, fmt.Sprintf(`{"userinfo": %s}`, userInfoFromName(sessionInfo.username))
 }
 
 // decodeRawChallenge extract the base64 challenge and try to decrypt it with the private key.

internal/brokers/manager.go

@@ -163,10 +163,9 @@ func (m *Manager) NewSession(brokerID, username, lang, mode string) (sessionID s
 		return "", "", err
 	}
 
-	log.Debug(context.Background(), fmt.Sprintf("%s: New session for %q", sessionID, username))
-
 	m.transactionsToBrokerMu.Lock()
 	defer m.transactionsToBrokerMu.Unlock()
+	log.Debug(context.Background(), fmt.Sprintf("%s: New session for %q", sessionID, username))
 	m.transactionsToBroker[sessionID] = broker
 	return sessionID, encryptionKey, nil
 }
@@ -184,6 +183,8 @@ func (m *Manager) EndSession(sessionID string) error {
 	}
 
 	m.transactionsToBrokerMu.Lock()
+	log.Debug(context.Background(), fmt.Sprintf("%s: End session %q",
+		sessionID, m.transactionsToBroker[sessionID].Name))
 	delete(m.transactionsToBroker, sessionID)
 	m.transactionsToBrokerMu.Unlock()
 	return nil

internal/testsdetection/testsdetection_test.go

@@ -44,6 +44,9 @@ func TestMustBeTestingInProcess(t *testing.T) {
 			if testutils.CoverDirForTests() != "" {
 				args = append(args, "-cover")
 			}
+			if testutils.IsRace() {
+				args = append(args, "-race")
+			}
 			args = append(args, "testdata/binary.go")
 
 			// Execute our subprocess

internal/testutils/args.go

@@ -2,13 +2,21 @@ package testutils
 
 import (
 	"os"
+	"runtime/debug"
+	"strconv"
 	"strings"
 	"sync"
 )
 
 var (
-	isVerbose     bool
-	isVerboseOnce sync.Once
+	isAsan              bool
+	isAsanOnce          sync.Once
+	isRace              bool
+	isRaceOnce          sync.Once
+	isVerbose           bool
+	isVerboseOnce       sync.Once
+	sleepMultiplier     float64
+	sleepMultiplierOnce sync.Once
 )
 
 // IsVerbose returns whether the tests are running in verbose mode.
@@ -24,3 +32,62 @@ func IsVerbose() bool {
 	})
 	return isVerbose
 }
+
+func haveBuildFlag(flag string) bool {
+	b, ok := debug.ReadBuildInfo()
+	if !ok {
+		panic("could not read build info")
+	}
+
+	flag = "-" + flag
+	for _, s := range b.Settings {
+		if s.Key != flag {
+			continue
+		}
+		value, err := strconv.ParseBool(s.Value)
+		if err != nil {
+			panic(err)
+		}
+		return value
+	}
+
+	return false
+}
+
+// IsAsan returns whether the tests are running with address sanitizer.
+func IsAsan() bool {
+	isAsanOnce.Do(func() { isAsan = haveBuildFlag("asan") })
+	return isAsan
+}
+
+// IsRace returns whether the tests are running with thread sanitizer.
+func IsRace() bool {
+	isRaceOnce.Do(func() { isRace = haveBuildFlag("race") })
+	return isRace
+}
+
+// SleepMultiplier returns the sleep multiplier to be used in tests.
+func SleepMultiplier() float64 {
+	sleepMultiplierOnce.Do(func() {
+		sleepMultiplier = 1
+		if v := os.Getenv("AUTHD_TESTS_SLEEP_MULTIPLIER"); v != "" {
+			var err error
+			sleepMultiplier, err = strconv.ParseFloat(v, 64)
+			if err != nil {
+				panic(err)
+			}
+			if sleepMultiplier <= 0 {
+				panic("Negative or 0 sleep multiplier is not supported")
+			}
+		}
+
+		if IsAsan() {
+			sleepMultiplier *= 1.5
+		}
+		if IsRace() {
+			sleepMultiplier *= 4
+		}
+	})
+
+	return sleepMultiplier
+}