From 16668b3cbe4430a402f4fb3594dd40a347584ca7 Mon Sep 17 00:00:00 2001 From: jacov Date: Thu, 7 Aug 2025 01:34:25 +0200 Subject: [PATCH 1/3] Auth check logger (ASG-4837) New feature for authaus to support "auth check" logging for usage analysis. Features - Log auth check endpoint calls - Flush periodically to db - User identity, token and timestamp is stored - Limit memory consumption on persistance bottlenecks Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> --- .gitignore | 10 +- all_test.go | 4 +- auth.go | 29 ++- config.go | 18 ++ go.mod | 1 + go.sum | 2 + migrations.go | 3 + msaad_test.go | 2 +- permitchecklog.go | 204 +++++++++++++++ permitchecklog_test.go | 323 ++++++++++++++++++++++++ query/auth_check_raw_data.sql | 10 + query/auth_check_tracking_analytics.sql | 32 +++ testutils.go | 7 +- 13 files changed, 631 insertions(+), 14 deletions(-) create mode 100644 permitchecklog.go create mode 100644 permitchecklog_test.go create mode 100644 query/auth_check_raw_data.sql create mode 100644 query/auth_check_tracking_analytics.sql diff --git a/.gitignore b/.gitignore index aa7863f..ca5558e 100644 --- a/.gitignore +++ b/.gitignore @@ -1,4 +1,10 @@ .idea/ -test-out/ -/testconf/ +/authaus.out /log/ +/testconf/ +test-out/ +/out +/test.log +/test-2025-08-07T06-17-16.613.log +/test-2025-08-07T06-18-32.789.log +/TestAuthRoleDB_MissingGroups_in_github_com_IMQS_authaus.test.exe diff --git a/all_test.go b/all_test.go index 2379928..765bba4 100644 --- a/all_test.go +++ b/all_test.go @@ -199,7 +199,7 @@ func getCentral(t *testing.T) *Central { userStore = newDummyUserStore() } - c := NewCentral(log.Stdout, nil, nil, userStore, permitDB, sessionDB, roleDB) + c := NewCentral(log.Stdout, nil, nil, userStore, permitDB, sessionDB, roleDB, nil) c.Auditor = &dummyAuditor{} if isBackendPostgresTest() { c.DB = sqlDB @@ -371,6 +371,8 @@ func sqlDeleteAllTables(db *sql.DB) error { "DROP TABLE IF EXISTS oauthchallenge CASCADE", "DROP TABLE IF EXISTS oauthsession CASCADE", "DROP TABLE IF EXISTS migration_version CASCADE", + "DROP TABLE IF EXISTS authuserstats CASCADE", + "DROP TABLE IF EXISTS session_check_logs CASCADE", } for _, st := range statements { if _, err := db.Exec(st); err != nil { diff --git a/auth.go b/auth.go index 8650a2e..7190e5c 100644 --- a/auth.go +++ b/auth.go @@ -313,6 +313,7 @@ type Central struct { permitDB PermitDB sessionDB SessionDB roleGroupDB RoleGroupDB + UsageTracker *CheckUsageTracker renameLock sync.Mutex loginDelayMS uint64 // Number of milliseconds by which we increase the delay login every time the user enters invalid credentials shuttingDown uint32 @@ -326,7 +327,7 @@ type Central struct { // Create a new Central object from the specified pieces. // roleGroupDB may be nil -func NewCentral(logfile string, ldap LDAP, msaad MSAADInterface, userStore UserStore, permitDB PermitDB, sessionDB SessionDB, roleGroupDB RoleGroupDB) *Central { +func NewCentral(logfile string, ldap LDAP, msaad MSAADInterface, userStore UserStore, permitDB PermitDB, sessionDB SessionDB, roleGroupDB RoleGroupDB, usageTracker *CheckUsageTracker) *Central { c := &Central{} c.OAuth.Initialize(c) @@ -361,6 +362,10 @@ func NewCentral(logfile string, ldap LDAP, msaad MSAADInterface, userStore UserS } } + if usageTracker != nil { + c.UsageTracker = usageTracker + c.UsageTracker.Initialize(c.Log) + } c.Log.Infof("Authaus successfully started up\n") return c @@ -369,13 +374,14 @@ func NewCentral(logfile string, ldap LDAP, msaad MSAADInterface, userStore UserS // Create a new 'Central' object from a Config. func NewCentralFromConfig(config *Config) (central *Central, err error) { var ( - db *sql.DB - ldap LDAP - msaad MSAADInterface - userStore UserStore - permitDB PermitDB - sessionDB SessionDB - roleGroupDB RoleGroupDB + db *sql.DB + ldap LDAP + msaad MSAADInterface + userStore UserStore + permitDB PermitDB + sessionDB SessionDB + roleGroupDB RoleGroupDB + checkUsageTracker *CheckUsageTracker ) msaadUsed := config.MSAAD.ClientID != "" ldapUsed := len(config.LDAP.LdapHost) > 0 @@ -460,8 +466,9 @@ func NewCentralFromConfig(config *Config) (central *Central, err error) { oldPasswordHistorySize = defaultOldPasswordHistorySize } userStore.SetConfig(time.Duration(config.UserStore.PasswordExpirySeconds)*time.Second, oldPasswordHistorySize, config.UserStore.UsersExemptFromExpiring) + checkUsageTracker = NewCheckUsageTracker(config.UsageTracking, nil, db) - c := NewCentral(config.Log.Filename, ldap, msaad, userStore, permitDB, sessionDB, roleGroupDB) + c := NewCentral(config.Log.Filename, ldap, msaad, userStore, permitDB, sessionDB, roleGroupDB, checkUsageTracker) c.DB = db c.MaxActiveSessions = config.SessionDB.MaxActiveSessions if config.SessionDB.SessionExpirySeconds != 0 { @@ -1197,6 +1204,10 @@ func (x *Central) Close() { x.roleGroupDB.Close() x.roleGroupDB = nil } + if x.UsageTracker != nil { + x.UsageTracker.Stop() + x.UsageTracker = nil + } if x.DB != nil { x.DB.Close() } diff --git a/config.go b/config.go index 961afb4..68384e5 100644 --- a/config.go +++ b/config.go @@ -166,6 +166,23 @@ type ConfigUserStoreDB struct { UsersExemptFromExpiring []string // List of users that are not subject to password expiry. Username will be used for comparison. } +// UsageTrackingConfig controls session check usage tracking +type ConfigUsageTracking struct { + Enabled bool `json:"enabled"` // Enable/disable usage tracking + FlushInterval int `json:"flush_interval"` // Flush interval in seconds (default: 60) + MaxEntries int `json:"max_entries"` // Maximum number of entries to keep in memory before flushing (default: 1000) + Test_MemDump bool `json:"test___mem_dump"` // If true, dump memory usage statistics to log on flush +} + +func (x *ConfigUsageTracking) SetDefaults() { + if x.FlushInterval <= 0 { + x.FlushInterval = 60 // Default to 1 minute + } + if x.MaxEntries <= 0 { + x.MaxEntries = 10000 // Default to 1000 entries + } +} + /* Configuration information. This is typically loaded from a .json config file. */ @@ -178,6 +195,7 @@ type Config struct { UserStore ConfigUserStoreDB OAuth ConfigOAuth MSAAD ConfigMSAAD + UsageTracking ConfigUsageTracking AuditServiceUrl string EnableAccountLocking bool MaxFailedLoginAttempts int diff --git a/go.mod b/go.mod index 3afe0f0..cb1ed50 100644 --- a/go.mod +++ b/go.mod @@ -11,6 +11,7 @@ require ( github.com/stretchr/testify v1.9.0 github.com/wI2L/jsondiff v0.6.1 golang.org/x/crypto v0.31.0 + golang.org/x/text v0.21.0 ) require ( diff --git a/go.sum b/go.sum index ed65c02..cc8556f 100644 --- a/go.sum +++ b/go.sum @@ -30,6 +30,8 @@ github.com/wI2L/jsondiff v0.6.1 h1:ISZb9oNWbP64LHnu4AUhsMF5W0FIj5Ok3Krip9Shqpw= github.com/wI2L/jsondiff v0.6.1/go.mod h1:KAEIojdQq66oJiHhDyQez2x+sRit0vIzC9KeK0yizxM= golang.org/x/crypto v0.31.0 h1:ihbySMvVjLAeSH1IbfcRTkD/iNscyz8rGzjF/E5hV6U= golang.org/x/crypto v0.31.0/go.mod h1:kDsLvtWBEx7MV9tJOj9bnXsPbxwJQ6csT/x4KIN4Ssk= +golang.org/x/text v0.21.0 h1:zyQAAkrwaneQ066sspRyJaG9VNi/YJ1NfzcGB3hZ/qo= +golang.org/x/text v0.21.0/go.mod h1:4IBbMaMmOPCJ8SecivzSH54+73PCFmPWxNTLm+vZkEQ= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405 h1:yhCVgyC4o1eVCa2tZl7eS0r+SDo693bJlVdllGtEeKM= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc= diff --git a/migrations.go b/migrations.go index 6d82060..7be3d7e 100644 --- a/migrations.go +++ b/migrations.go @@ -282,6 +282,9 @@ func createMigrations() []migration.Migrator { // 16. Add authuserstats table that will record user_id, enabled_date, disabled_date, last_login_date simple(`CREATE TABLE authuserstats (user_id BIGINT PRIMARY KEY, enabled_date TIMESTAMP, disabled_date TIMESTAMP, last_login_date TIMESTAMP);`), + + // 17. Add: session_check_logs + simple(`CREATE TABLE session_check_logs (id bigserial PRIMARY KEY, ts TIMESTAMP WITH TIME ZONE NOT NULL, session_token VARCHAR NOT NULL, user_id BIGINT NOT NULL);`), } } diff --git a/msaad_test.go b/msaad_test.go index be3ccca..311fa41 100644 --- a/msaad_test.go +++ b/msaad_test.go @@ -178,7 +178,7 @@ func getCentralMSAAD(t *testing.T) *Central { p.Roles = EncodePermit(groupIds) permitDB.SetPermit(user.UserId, &p) - c := NewCentral(log.Stdout, nil, &msaad, userStore, permitDB, sessionDB, roleDB) + c := NewCentral(log.Stdout, nil, &msaad, userStore, permitDB, sessionDB, roleDB, nil) da := &dummyAuditor{} da.messages = []string{} da.testing = t diff --git a/permitchecklog.go b/permitchecklog.go new file mode 100644 index 0000000..a6540f1 --- /dev/null +++ b/permitchecklog.go @@ -0,0 +1,204 @@ +package authaus + +import ( + "database/sql" + "fmt" + "github.com/IMQS/log" + "sync" + "time" +) + +// CheckLogEntry represents a single session check log entry +type CheckLogEntry struct { + Timestamp time.Time `json:"timestamp"` + SessionToken string `json:"session_token"` + UserId UserId `json:"user_id"` +} + +// CheckUsageTracker manages in-memory storage and periodic flushing of session check logs +type CheckUsageTracker struct { + config ConfigUsageTracking + log *log.Logger + logs []CheckLogEntry + mutex sync.RWMutex + stopChan chan struct{} + doneChan chan struct{} + flushDoneChan chan struct{} + stopOnce sync.Once + flushTicker *time.Ticker + flushing bool // Track if a flush is in progress + db *sql.DB + droppedLogsCount int64 + memDump []string // For testing purposes +} + +// NewCheckUsageTracker creates a new usage tracker instance +func NewCheckUsageTracker(c ConfigUsageTracking, log *log.Logger, db *sql.DB) *CheckUsageTracker { + c.SetDefaults() + tracker := &CheckUsageTracker{ + config: c, + log: log, + logs: make([]CheckLogEntry, 0), + stopChan: make(chan struct{}), + doneChan: make(chan struct{}), + flushDoneChan: make(chan struct{}, 1), + db: db, // Database connection will be set later + } + if tracker.config.Test_MemDump { + tracker.memDump = make([]string, 0) + } + return tracker +} + +func (t *CheckUsageTracker) Initialize(logger *log.Logger) { + if logger != nil { + t.log = logger + + if t.config.Enabled { + t.start() + } + + if t.db == nil { + t.log.Warn("CheckUsageTracker initialized without a database connection, logs will not be persisted") + } else { + t.log.Info("CheckUsageTracker initialized with database connection") + } + } +} + +// LogCheck adds a check request to the in-memory log +func (t *CheckUsageTracker) LogCheck(sessionToken string, token *Token) { + if !t.config.Enabled { + return + } + + entry := CheckLogEntry{ + Timestamp: time.Now().UTC(), + SessionToken: sessionToken, + UserId: token.UserId, + } + + t.mutex.Lock() + if len(t.logs) >= t.config.MaxEntries { + t.droppedLogsCount++ + // drop entry + } else { + t.logs = append(t.logs, entry) + } + t.mutex.Unlock() +} + +// start begins the periodic flush process +func (t *CheckUsageTracker) start() { + flushInterval := time.Duration(t.config.FlushInterval) * time.Second + if flushInterval <= 0 { + flushInterval = 60 * time.Second // Default to 1 minute + } + + t.flushTicker = time.NewTicker(flushInterval) + + go func() { + defer close(t.doneChan) + for { + select { + case <-t.flushTicker.C: + t.flush() + case <-t.stopChan: + t.flushTicker.Stop() + t.flush() // Final flush before stopping + return + } + } + }() +} + +// Stop gracefully shuts down the usage tracker +func (t *CheckUsageTracker) Stop() { + t.stopOnce.Do(func() { + if t.flushTicker != nil && t.stopChan != nil { + close(t.stopChan) + <-t.doneChan // Wait for main flush management goroutine to finish + <-t.flushDoneChan // Wait for any ongoing flush operation to complete + } + }) +} + +// flush writes the in-memory logs to persistent storage and clears the memory +// TODO : Implement a more generic persistence abstraction (e.g. Provider pattern) +func (t *CheckUsageTracker) flush() { + t.mutex.Lock() + + if len(t.logs) == 0 || t.flushing { + t.mutex.Unlock() + return + } + + // Create a copy of logs to persist + logsToPersist := make([]CheckLogEntry, len(t.logs)) + copy(logsToPersist, t.logs) + logsCount := len(t.logs) + + // Mark that we're flushing to prevent concurrent flushes + t.flushing = true + t.mutex.Unlock() + + // Persist logs in a separate goroutine to avoid blocking + go func() { + err := t.persistLogs(logsToPersist) + + // Handle the result of persistence + t.mutex.Lock() + t.flushing = false + + if err != nil { + t.log.Errorf("Failed to persist check usage logs: %v", err) + // Keep the logs in memory for retry - don't clear them + } else { + // Only clear logs after successful persistence + // Check if new logs were added during persistence + if len(t.logs) >= logsCount { + // Remove the persisted logs (first logsCount entries) + t.logs = t.logs[logsCount:] + } else { + // Shouldn't happen, but clear all if somehow we have fewer logs + t.logs = t.logs[:0] + } + } + t.mutex.Unlock() + t.flushDoneChan <- struct{}{} + }() +} + +// persistLogs writes logs to persistent storage using authaus persistence abstraction +func (t *CheckUsageTracker) persistLogs(logs []CheckLogEntry) error { + if t.db != nil { + // Example SQL insert statement, assuming a table structure exists + stmt, err := t.db.Prepare("INSERT INTO session_check_logs (ts, session_token, user_id) VALUES ($1, $2, $3)") + if err != nil { + return err + } + defer stmt.Close() + + for _, entry := range logs { + _, err = stmt.Exec(entry.Timestamp, entry.SessionToken, entry.UserId) + if err != nil { + return err + } + } + } else { + // this is for testing, NOT production + if t.config.Test_MemDump { + // If no database connection, just clear + for _, entry := range logs { + t.memDump = append(t.memDump, checkLogString(entry)) + } + } + } + return nil +} + +func checkLogString(entry CheckLogEntry) string { + return "Persisting CheckUsage: time=" + entry.Timestamp.Format(time.RFC3339) + + " token=" + entry.SessionToken + + " userId=" + fmt.Sprint(entry.UserId) +} diff --git a/permitchecklog_test.go b/permitchecklog_test.go new file mode 100644 index 0000000..5dfb016 --- /dev/null +++ b/permitchecklog_test.go @@ -0,0 +1,323 @@ +package authaus + +import ( + "github.com/IMQS/log" + "github.com/stretchr/testify/assert" + "golang.org/x/text/language" + "golang.org/x/text/message" + "runtime" + "strconv" + "testing" + "time" +) + +func TestConfigUsageTracking_SetDefaults(t *testing.T) { + config := &ConfigUsageTracking{} + config.SetDefaults() + + assert.Equal(t, 60, config.FlushInterval, "FlushInterval should be 60 after SetDefaults") + assert.Equal(t, 10000, config.MaxEntries, "MaxEntries should be 10000 after SetDefaults") +} + +func TestCheckUsageTracker_LogCheck_Disabled(t *testing.T) { + // Test that when usage tracking is disabled, LogCheck does nothing + config := ConfigUsageTracking{Enabled: false} + tracker := NewCheckUsageTracker(config, testLogStdOut(), nil) + + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + // This should not panic or cause issues when disabled + tracker.LogCheck("session123", token) + + // Should have no logs + tracker.mutex.RLock() + logCount := len(tracker.logs) + tracker.mutex.RUnlock() + + assert.Equal(t, 0, logCount, "Expected no logs when usage tracking is disabled") +} + +func TestCheckUsageTracker_LogCheck_Enabled(t *testing.T) { + // Test that when usage tracking is enabled, LogCheck stores entries + config := ConfigUsageTracking{Enabled: true, FlushInterval: 60} + tracker := NewCheckUsageTracker(config, testLogStdOut(), nil) + defer tracker.Stop() + + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + sessionToken := "session123" + tracker.LogCheck(sessionToken, token) + + // Verify log was created + tracker.mutex.RLock() + logCount := len(tracker.logs) + if logCount != 1 { + t.Errorf("Expected 1 log entry, got %d", logCount) + } else { + entry := tracker.logs[0] + assert.Equal(t, entry.SessionToken, sessionToken, "Expected session token to match") + assert.Equal(t, entry.UserId, token.UserId, "Expected userId to match") + assert.True(t, !entry.Timestamp.IsZero(), "Expected timestamp to be set") + } + tracker.mutex.RUnlock() +} + +func TestCheckUsageTracker_FlushBehavior(t *testing.T) { + // Test that flush handles persistence failures correctly + config := ConfigUsageTracking{Enabled: true, FlushInterval: 1} + tracker := NewCheckUsageTracker(config, testLogStdOut(), nil) + defer tracker.Stop() + + // Add some logs + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + tracker.LogCheck("session1", token) + tracker.LogCheck("session2", token) + + // Verify logs exist before flush + tracker.mutex.RLock() + initialCount := len(tracker.logs) + tracker.mutex.RUnlock() + + assert.Equal(t, 2, initialCount, "Expected 2 logs before flush") + + // Call flush manually + tracker.flush() + + // Wait a bit for the goroutine + <-tracker.flushDoneChan + + // Since persistLogs currently always succeeds, + // logs should be cleared after flush + tracker.mutex.RLock() + finalCount := len(tracker.logs) + flushing := tracker.flushing + tracker.mutex.RUnlock() + + assert.Equal(t, 0, finalCount, "Expected no logs after successful flush") + assert.False(t, flushing, "Expected flushing to be false after flush completes") +} + +func TestCheckUsageTracker_Overload(t *testing.T) { + config := ConfigUsageTracking{ + Enabled: true, + FlushInterval: 10, + MaxEntries: 1000, + Test_MemDump: true, + } + l := testLogStdOut() + tracker := NewCheckUsageTracker(config, l, nil) + tracker.Initialize(l) + defer tracker.Stop() + + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + maxSessions := 3000 + sessions := makeSessions(maxSessions) + // add all sessions immediately, which should exceed capacity + for i := 0; i < maxSessions; i++ { + tracker.LogCheck(sessions[i], token) + } + + tracker.mutex.RLock() + initialCount := len(tracker.logs) + droppedCount := tracker.droppedLogsCount + tracker.mutex.RUnlock() + t.Logf("Initial log count: %d, Dropped count: %d", initialCount, droppedCount) + assert.Equal(t, config.MaxEntries, initialCount, "Expect only 1000 entries to be 'persisted'") + assert.Equal(t, int64(maxSessions-config.MaxEntries), droppedCount, "Expect 1000 entries to be dropped due to overload") +} + +// TODO : Find a more comprehensive way to test performance +func TestCheckUsageTracker_Perf(t *testing.T) { + config := ConfigUsageTracking{ + Enabled: true, + FlushInterval: 1, + MaxEntries: 300000, + Test_MemDump: true, + } + l := testLogStdOut() + tracker := NewCheckUsageTracker(config, l, nil) + tracker.Initialize(l) + defer tracker.Stop() + + // Add some logs + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + maxSessions := 300000 + sessions := makeSessions(maxSessions) + + ms1 := time.Now().UnixMilli() + for i := 0; i < maxSessions; i++ { + tracker.LogCheck(sessions[i], token) + } + ms2 := time.Now().UnixMilli() + // Verify logs exist before flush + msTotal := ms2 - ms1 + assert.Less(t, ms2-ms1, (1 * time.Second).Milliseconds(), "Expected less than 1 second for logging %d sessions", maxSessions) + p := message.NewPrinter(language.Afrikaans) + t.Log(p.Printf("Total time for %d logs: %d %s", maxSessions, msTotal, "ms")) + + tracker.mutex.RLock() + initialCount := len(tracker.logs) + tracker.mutex.RUnlock() + + assert.Equal(t, maxSessions, initialCount, "Expected %d logs before flush", maxSessions) + // Call flush manually + tracker.flush() + t.Log("Before 'Stop'") + tracker.Stop() + t.Log("After 'Stop'") + + // Since persistLogs currently always succeeds (just logs), + // all logs should be cleared after flush + tracker.mutex.RLock() + finalCount := len(tracker.logs) + persistCount := len(tracker.memDump) + flushing := tracker.flushing + droppedCount := tracker.droppedLogsCount + tracker.mutex.RUnlock() + t.Logf("Final log count: %d, Persist count: %d, Dropped count: %d, Flushing: %t", finalCount, persistCount, droppedCount, flushing) + + assert.Equal(t, 0, finalCount, "Expected no logs after flush") + assert.Equal(t, maxSessions, persistCount, "Expected memDump to contain %d entries", maxSessions) + assert.Equal(t, 0, droppedCount, "Expected no dropped logs") + if flushing { + t.Error("Expected flushing to be false after flush completes") + } + assert.NotEqual(t, flushing, true, "Expected flushing to be false after flush completes") +} + +func TestCheckUsageTracker_NormalFlush(t *testing.T) { + config := ConfigUsageTracking{ + Enabled: true, + FlushInterval: 1, + MaxEntries: 100000, + Test_MemDump: true, + } + + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + maxSessions := 10000 + sessions := makeSessions(maxSessions) + + l := testLogStdOut() + tracker := NewCheckUsageTracker(config, l, nil) + tracker.Initialize(l) + defer tracker.Stop() + + for i := 0; i < maxSessions; i++ { + tracker.LogCheck("session"+sessions[i], token) + } + + // Verify logs exist before flush + tracker.mutex.RLock() + initialCount := len(tracker.logs) + tracker.mutex.RUnlock() + + assert.Equal(t, maxSessions, initialCount, "Expected %d logs before flush", maxSessions) + + // wait at least flush interval + time.Sleep(1*time.Second + 100*time.Millisecond) + + // Since persistLogs currently always succeeds (just logs), + // all logs should be cleared after flush interval + tracker.mutex.RLock() + finalCount := len(tracker.logs) + persistCount := len(tracker.memDump) + flushing := tracker.flushing + droppedCount := tracker.droppedLogsCount + tracker.mutex.RUnlock() + t.Logf("Final log count: %d, Persist count: %d, Dropped count: %d, Flushing: %t", finalCount, persistCount, droppedCount, flushing) + + assert.Equal(t, 0, finalCount, "Expected no logs after flush") + assert.Equal(t, maxSessions, persistCount, "Expected memDump to contain %d entries", maxSessions) + assert.Equal(t, int64(0), droppedCount, "Expected no dropped logs") + assert.False(t, flushing, "Expected flushing to be false after flush completes") +} + +func TestCheckUsageTracker_FinalFlush(t *testing.T) { + config := ConfigUsageTracking{ + Enabled: true, + FlushInterval: 1, + MaxEntries: 100000, + Test_MemDump: true, + } + + token := &Token{ + Identity: "testuser", + UserId: 1, + Username: "testuser", + Email: "test@example.com", + } + + maxSessions := 10000 + sessions := makeSessions(maxSessions) + + l := testLogStdOut() + tracker := NewCheckUsageTracker(config, l, nil) + tracker.Initialize(l) + defer tracker.Stop() + + for i := 0; i < maxSessions; i++ { + tracker.LogCheck("session"+sessions[i], token) + } + + // Verify logs exist before flush + tracker.mutex.RLock() + initialCount := len(tracker.logs) + tracker.mutex.RUnlock() + assert.Equal(t, maxSessions, initialCount, "Expected %d logs before final flush", maxSessions) + + //stop tracker (expect to flush automatically) + tracker.Stop() + time.Sleep(100 * time.Millisecond) + tracker.mutex.RLock() + finalCount := len(tracker.logs) + tracker.mutex.RUnlock() + assert.Equal(t, 0, finalCount, "Expected no logs after final flush") +} + +func makeSessions(maxSessions int) []string { + sessions := make([]string, maxSessions) + for k := 0; k < maxSessions; k++ { + i := k % 10 // Use 10 different session tokens to simulate real usage + sessions[k] = "session" + string(strconv.Itoa(i)) + } + return sessions +} + +func testLogStdOut() *log.Logger { + log1 := log.New(resolveLogfile(log.Stdout), runtime.GOOS != "windows") + return log1 +} diff --git a/query/auth_check_raw_data.sql b/query/auth_check_raw_data.sql new file mode 100644 index 0000000..e65cf33 --- /dev/null +++ b/query/auth_check_raw_data.sql @@ -0,0 +1,10 @@ +SELECT * +FROM public.session_check_logs +ORDER BY + id ASC LIMIT 100 + +select scl.*, aus.username, aus.email +from + public.session_check_logs scl +-- left join authsession a on a.sessionkey = scl.session_token + left join authuserstore aus on aus.userid = scl.user_id \ No newline at end of file diff --git a/query/auth_check_tracking_analytics.sql b/query/auth_check_tracking_analytics.sql new file mode 100644 index 0000000..6fe492f --- /dev/null +++ b/query/auth_check_tracking_analytics.sql @@ -0,0 +1,32 @@ +WITH time_buckets AS ( + SELECT + date_trunc('minute', ts) - (extract(minute from ts)::int % 5) * interval '1 minute' AS time_bucket, + user_id, + COUNT(*) AS user_requests +FROM public.session_check_logs +GROUP BY time_bucket, user_id + ), + stats AS ( +SELECT + time_bucket, + COUNT(*) AS unique_users, + SUM(user_requests) AS total_requests, + AVG(user_requests::numeric) AS mean_requests, + STDDEV_POP(user_requests::numeric) AS stddev_requests +FROM time_buckets +GROUP BY time_bucket + ) +SELECT + time_bucket, + unique_users, + total_requests, + ROUND(mean_requests, 2) AS mean_requests, + ROUND(stddev_requests, 2) AS stddev_requests, + ROUND( + CASE + WHEN mean_requests > 0 THEN stddev_requests / mean_requests + ELSE NULL + END, 2 + ) AS coefficient_of_variation +FROM stats +ORDER BY time_bucket; diff --git a/testutils.go b/testutils.go index f772b86..a865e51 100644 --- a/testutils.go +++ b/testutils.go @@ -5,6 +5,11 @@ func NewCentralDummy(logfile string) *Central { sessionDB := newDummySessionDB() permitDB := newDummyPermitDB() roleGroupDB := newDummyRoleGroupDB() - central := NewCentral(logfile, nil, nil, userStore, permitDB, sessionDB, roleGroupDB) + usageTracker := NewCheckUsageTracker(ConfigUsageTracking{ + Enabled: false, + FlushInterval: 10, + }, nil, nil) + central := NewCentral(logfile, nil, nil, userStore, permitDB, sessionDB, roleGroupDB, usageTracker) + return central } From fac5726aedc6e73b40abda6a1ba88773e8cb46e6 Mon Sep 17 00:00:00 2001 From: jacov Date: Wed, 8 Oct 2025 02:03:28 +0200 Subject: [PATCH 2/3] Rename config fieldnames --- config.go | 14 +++++++------- permitchecklog.go | 2 +- permitchecklog_test.go | 38 +++++++++++++++++++------------------- testutils.go | 4 ++-- 4 files changed, 29 insertions(+), 29 deletions(-) diff --git a/config.go b/config.go index 68384e5..4ca3cf3 100644 --- a/config.go +++ b/config.go @@ -168,18 +168,18 @@ type ConfigUserStoreDB struct { // UsageTrackingConfig controls session check usage tracking type ConfigUsageTracking struct { - Enabled bool `json:"enabled"` // Enable/disable usage tracking - FlushInterval int `json:"flush_interval"` // Flush interval in seconds (default: 60) - MaxEntries int `json:"max_entries"` // Maximum number of entries to keep in memory before flushing (default: 1000) - Test_MemDump bool `json:"test___mem_dump"` // If true, dump memory usage statistics to log on flush + Enabled bool `json:"enabled"` // Enable/disable usage tracking + FlushIntervalSeconds int `json:"flush_interval_seconds"` // Flush interval in seconds (default: 60) + MaxEntries int `json:"max_entries"` // Maximum number of entries to keep in memory before flushing (default: 1000) + Test_MemDump bool `json:"test___mem_dump"` // If true, dump memory usage statistics to log on flush } func (x *ConfigUsageTracking) SetDefaults() { - if x.FlushInterval <= 0 { - x.FlushInterval = 60 // Default to 1 minute + if x.FlushIntervalSeconds <= 0 { + x.FlushIntervalSeconds = 60 // Default to 1 minute } if x.MaxEntries <= 0 { - x.MaxEntries = 10000 // Default to 1000 entries + x.MaxEntries = 10000 // Default to 10000 entries } } diff --git a/permitchecklog.go b/permitchecklog.go index a6540f1..9574b79 100644 --- a/permitchecklog.go +++ b/permitchecklog.go @@ -90,7 +90,7 @@ func (t *CheckUsageTracker) LogCheck(sessionToken string, token *Token) { // start begins the periodic flush process func (t *CheckUsageTracker) start() { - flushInterval := time.Duration(t.config.FlushInterval) * time.Second + flushInterval := time.Duration(t.config.FlushIntervalSeconds) * time.Second if flushInterval <= 0 { flushInterval = 60 * time.Second // Default to 1 minute } diff --git a/permitchecklog_test.go b/permitchecklog_test.go index 5dfb016..10a4455 100644 --- a/permitchecklog_test.go +++ b/permitchecklog_test.go @@ -15,7 +15,7 @@ func TestConfigUsageTracking_SetDefaults(t *testing.T) { config := &ConfigUsageTracking{} config.SetDefaults() - assert.Equal(t, 60, config.FlushInterval, "FlushInterval should be 60 after SetDefaults") + assert.Equal(t, 60, config.FlushIntervalSeconds, "FlushIntervalSeconds should be 60 after SetDefaults") assert.Equal(t, 10000, config.MaxEntries, "MaxEntries should be 10000 after SetDefaults") } @@ -44,7 +44,7 @@ func TestCheckUsageTracker_LogCheck_Disabled(t *testing.T) { func TestCheckUsageTracker_LogCheck_Enabled(t *testing.T) { // Test that when usage tracking is enabled, LogCheck stores entries - config := ConfigUsageTracking{Enabled: true, FlushInterval: 60} + config := ConfigUsageTracking{Enabled: true, FlushIntervalSeconds: 60} tracker := NewCheckUsageTracker(config, testLogStdOut(), nil) defer tracker.Stop() @@ -74,7 +74,7 @@ func TestCheckUsageTracker_LogCheck_Enabled(t *testing.T) { func TestCheckUsageTracker_FlushBehavior(t *testing.T) { // Test that flush handles persistence failures correctly - config := ConfigUsageTracking{Enabled: true, FlushInterval: 1} + config := ConfigUsageTracking{Enabled: true, FlushIntervalSeconds: 1} tracker := NewCheckUsageTracker(config, testLogStdOut(), nil) defer tracker.Stop() @@ -115,10 +115,10 @@ func TestCheckUsageTracker_FlushBehavior(t *testing.T) { func TestCheckUsageTracker_Overload(t *testing.T) { config := ConfigUsageTracking{ - Enabled: true, - FlushInterval: 10, - MaxEntries: 1000, - Test_MemDump: true, + Enabled: true, + FlushIntervalSeconds: 10, + MaxEntries: 1000, + Test_MemDump: true, } l := testLogStdOut() tracker := NewCheckUsageTracker(config, l, nil) @@ -151,10 +151,10 @@ func TestCheckUsageTracker_Overload(t *testing.T) { // TODO : Find a more comprehensive way to test performance func TestCheckUsageTracker_Perf(t *testing.T) { config := ConfigUsageTracking{ - Enabled: true, - FlushInterval: 1, - MaxEntries: 300000, - Test_MemDump: true, + Enabled: true, + FlushIntervalSeconds: 1, + MaxEntries: 300000, + Test_MemDump: true, } l := testLogStdOut() tracker := NewCheckUsageTracker(config, l, nil) @@ -215,10 +215,10 @@ func TestCheckUsageTracker_Perf(t *testing.T) { func TestCheckUsageTracker_NormalFlush(t *testing.T) { config := ConfigUsageTracking{ - Enabled: true, - FlushInterval: 1, - MaxEntries: 100000, - Test_MemDump: true, + Enabled: true, + FlushIntervalSeconds: 1, + MaxEntries: 100000, + Test_MemDump: true, } token := &Token{ @@ -268,10 +268,10 @@ func TestCheckUsageTracker_NormalFlush(t *testing.T) { func TestCheckUsageTracker_FinalFlush(t *testing.T) { config := ConfigUsageTracking{ - Enabled: true, - FlushInterval: 1, - MaxEntries: 100000, - Test_MemDump: true, + Enabled: true, + FlushIntervalSeconds: 1, + MaxEntries: 100000, + Test_MemDump: true, } token := &Token{ diff --git a/testutils.go b/testutils.go index a865e51..5aa80ae 100644 --- a/testutils.go +++ b/testutils.go @@ -6,8 +6,8 @@ func NewCentralDummy(logfile string) *Central { permitDB := newDummyPermitDB() roleGroupDB := newDummyRoleGroupDB() usageTracker := NewCheckUsageTracker(ConfigUsageTracking{ - Enabled: false, - FlushInterval: 10, + Enabled: false, + FlushIntervalSeconds: 10, }, nil, nil) central := NewCentral(logfile, nil, nil, userStore, permitDB, sessionDB, roleGroupDB, usageTracker) From 8349139b93687042432ad7c4c4679a339a79277d Mon Sep 17 00:00:00 2001 From: jacov Date: Thu, 9 Oct 2025 11:48:11 +0200 Subject: [PATCH 3/3] Changelog --- docs/changelog.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/docs/changelog.md b/docs/changelog.md index 54725db..27c9330 100644 --- a/docs/changelog.md +++ b/docs/changelog.md @@ -2,6 +2,8 @@ ## Current +* feat : Auth-check logger (ASG-4837) + ## v1.3.8 * fix : Add fetch-all for UserStats to combat performance issues