Add configurable authentication logging via SERVICE_AUTH_VERBOSE flag

docs/content/deployment/environment-variables.md

@@ -108,6 +108,51 @@ SERVICE_DEBUG=true    # Development (verbose)
 - `true`: Detailed logs, useful for debugging
 - `false`: Minimal logs, recommended for production
 
+### SERVICE_AUTH_VERBOSE
+
+Enable verbose authentication logging.
+
+- **Type:** Boolean
+- **Required:** No
+- **Default:** `false`
+- **Environment Variable:** `SERVICE_AUTH_VERBOSE`
+- **Command-line Flag:** `--auth-verbose`
+
+**Description:** Controls authentication log output. When enabled, logs all authentication attempts including successful and failed authentications. When disabled (default), authentication operates silently.
+
+**Example:**
+
+```bash
+SERVICE_AUTH_VERBOSE=false   # Quiet mode (default, recommended for production)
+SERVICE_AUTH_VERBOSE=true    # Verbose mode (useful for debugging)
+```
+
+**Use Cases:**
+
+- **`true` (verbose mode):** 
+  - Debugging authentication issues
+  - Monitoring security events
+  - Development and testing
+  - Auditing access patterns
+
+- **`false` (quiet mode, recommended):**
+  - Production environments
+  - Bulk upload operations
+  - High-traffic scenarios
+  - When crawlers or automated tools access the API frequently
+
+**Example Log Output (when `true`):**
+
+```
+    Owner authentication successful: alice
+    Reader auth for owner=bob project=test definition= instance= running...
+        Checking project access...
+        Reader authentication successful
+    Authentication failed.
+```
+
+**Note:** Authentication still functions normally when logging is disabled; only the console output is suppressed. This prevents log spam during bulk operations or high-traffic periods.
+
 ### SERVICE_HOST
 
 Hostname or IP address to bind the service to.
@@ -275,6 +320,7 @@ SERVICE_DBNAME=embapi_test     # Testing database
 ```bash
 # .env file for development
 SERVICE_DEBUG=true
+SERVICE_AUTH_VERBOSE=true
 SERVICE_HOST=localhost
 SERVICE_PORT=8880
 SERVICE_DBHOST=localhost
@@ -291,6 +337,7 @@ ENCRYPTION_KEY=dev-encryption-key-min-32-chars-long
 ```bash
 # .env file for Docker Compose
 SERVICE_DEBUG=false
+SERVICE_AUTH_VERBOSE=false
 SERVICE_HOST=0.0.0.0
 SERVICE_PORT=8880
 SERVICE_DBHOST=postgres
@@ -307,6 +354,7 @@ ENCRYPTION_KEY=generated_encryption_key_from_setup_script
 ```bash
 # .env file for production (or use secrets management)
 SERVICE_DEBUG=false
+SERVICE_AUTH_VERBOSE=false
 SERVICE_HOST=0.0.0.0
 SERVICE_PORT=8880
 SERVICE_DBHOST=db.internal.example.com
@@ -384,6 +432,7 @@ Some variables support command-line flags:
 ```bash
 ./embapi \
   --debug \
+  --auth-verbose \
   --host 0.0.0.0 \
   --port 8880 \
   --admin-key your-admin-key \

docs/content/getting-started/configuration.md

@@ -16,6 +16,7 @@ All configuration can be set via environment variables. Use a `.env` file to kee
 | Variable | Description | Default | Required |
 |----------|-------------|---------|----------|
 | `SERVICE_DEBUG` | Enable debug logging | `true` | No |
+| `SERVICE_AUTH_VERBOSE` | Enable verbose authentication logging | `false` | No |
 | `SERVICE_HOST` | Hostname to listen on | `localhost` | No |
 | `SERVICE_PORT` | Port to listen on | `8880` | No |
 
@@ -43,6 +44,7 @@ Create a `.env` file in the project root:
 ```bash
 # Service Configuration
 SERVICE_DEBUG=false
+SERVICE_AUTH_VERBOSE=false
 SERVICE_HOST=0.0.0.0
 SERVICE_PORT=8880
 
@@ -65,6 +67,7 @@ You can also provide configuration via command-line flags:
 ```bash
 ./embapi \
   --debug \
+  --auth-verbose \
   -p 8880 \
   --db-host localhost \
   --db-port 5432 \
@@ -116,6 +119,7 @@ Configuration is loaded in the following order (later sources override earlier o
 ```bash
 # .env (development)
 SERVICE_DEBUG=true
+SERVICE_AUTH_VERBOSE=true
 SERVICE_HOST=localhost
 SERVICE_PORT=8880
 SERVICE_DBHOST=localhost
@@ -132,6 +136,7 @@ ENCRYPTION_KEY=dev-encryption-key-32-chars-min
 ```bash
 # .env (production)
 SERVICE_DEBUG=false
+SERVICE_AUTH_VERBOSE=false
 SERVICE_HOST=0.0.0.0
 SERVICE_PORT=8880
 SERVICE_DBHOST=prod-db.example.com
@@ -143,6 +148,30 @@ SERVICE_ADMINKEY=$(cat /run/secrets/admin_key)
 ENCRYPTION_KEY=$(cat /run/secrets/encryption_key)
 ```
 
+## Logging Configuration
+
+### Authentication Logging
+
+The `SERVICE_AUTH_VERBOSE` flag controls authentication log output. This is particularly useful for production environments or during bulk operations:
+
+- **`SERVICE_AUTH_VERBOSE=true`** (verbose mode): Logs all authentication attempts, including successful and failed authentications. Useful for debugging authentication issues or monitoring security events.
+
+- **`SERVICE_AUTH_VERBOSE=false`** (quiet mode, default): Suppresses authentication logs. Recommended for production, especially during:
+  - Bulk upload operations
+  - High-traffic scenarios
+  - When crawlers or automated tools access the API frequently
+
+Example log output with `SERVICE_AUTH_VERBOSE=true`:
+```
+    Owner authentication successful: alice
+    Reader auth for owner=bob project=test definition= instance= running...
+        Checking project access...
+        Reader authentication successful
+    Authentication failed.
+```
+
+With `SERVICE_AUTH_VERBOSE=false`, these messages are suppressed while authentication still works normally.
+
 ## Validation
 
 The service validates configuration on startup and will exit with an error if required variables are missing.

internal/auth/auth_verbose_test.go

@@ -0,0 +1,229 @@
+package auth_test
+
+import (
+	"bytes"
+	"context"
+	"io"
+	"net/http"
+	"net/http/httptest"
+	"os"
+	"strings"
+	"testing"
+
+	"github.com/danielgtaylor/huma/v2"
+	"github.com/danielgtaylor/huma/v2/adapters/humago"
+	"github.com/mpilhlt/embapi/internal/auth"
+	"github.com/mpilhlt/embapi/internal/models"
+	"github.com/stretchr/testify/assert"
+)
+
+// TestAuthVerboseFlag tests that authentication logging is controlled by the AuthVerbose flag
+func TestAuthVerboseFlag(t *testing.T) {
+	// Set required environment variables for testing
+	if os.Getenv("ENCRYPTION_KEY") == "" {
+		os.Setenv("ENCRYPTION_KEY", "test-encryption-key-32-bytes-long-1234567890")
+	}
+
+	tests := []struct {
+		name        string
+		authVerbose bool
+		expectLogs  bool
+	}{
+		{
+			name:        "AuthVerbose=true should produce logs",
+			authVerbose: true,
+			expectLogs:  true,
+		},
+		{
+			name:        "AuthVerbose=false should suppress logs",
+			authVerbose: false,
+			expectLogs:  false,
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			// Capture stdout to check for log messages
+			oldStdout := os.Stdout
+			r, w, _ := os.Pipe()
+			os.Stdout = w
+
+			// Create test options
+			options := &models.Options{
+				AuthVerbose: tt.authVerbose,
+				AdminKey:    "test-admin-key",
+			}
+
+			// Create a simple API and router
+			config := huma.DefaultConfig("Test API", "1.0.0")
+			router := http.NewServeMux()
+			api := humago.New(router, config)
+
+			// Register auth middlewares
+			api.UseMiddleware(auth.EmbAPIKeyAdminAuth(api, options))
+			api.UseMiddleware(auth.AuthTermination(api, options))
+
+			// Register a test endpoint that requires authentication
+			huma.Register(api, huma.Operation{
+				OperationID: "test-endpoint",
+				Method:      http.MethodGet,
+				Path:        "/test",
+				Security: []map[string][]string{
+					{"adminAuth": {}},
+				},
+			}, func(ctx context.Context, input *struct{}) (*struct{}, error) {
+				return &struct{}{}, nil
+			})
+
+			// Test 1: Successful authentication (should log if verbose)
+			req1 := httptest.NewRequest(http.MethodGet, "/test", nil)
+			req1.Header.Set("Authorization", "Bearer test-admin-key")
+			resp1 := httptest.NewRecorder()
+			router.ServeHTTP(resp1, req1)
+
+			// Capture output
+			w.Close()
+			var buf bytes.Buffer
+			io.Copy(&buf, r)
+			os.Stdout = oldStdout
+			output := buf.String()
+
+			// Verify status code (204 No Content is expected for successful operation with no body)
+			assert.Equal(t, http.StatusNoContent, resp1.Code, "Expected successful authentication")
+
+			// Check for log output based on verbose flag
+			if tt.expectLogs {
+				assert.Contains(t, output, "Admin authentication successful", "Expected admin auth log when verbose=true")
+			} else {
+				assert.NotContains(t, output, "Admin authentication successful", "Expected no admin auth log when verbose=false")
+			}
+
+			// Test 2: Failed authentication (should log if verbose)
+			// Capture stdout again for failed auth test
+			r2, w2, _ := os.Pipe()
+			os.Stdout = w2
+
+			req2 := httptest.NewRequest(http.MethodGet, "/test", nil)
+			req2.Header.Set("Authorization", "Bearer wrong-key")
+			resp2 := httptest.NewRecorder()
+			router.ServeHTTP(resp2, req2)
+
+			// Capture output
+			w2.Close()
+			var buf2 bytes.Buffer
+			io.Copy(&buf2, r2)
+			os.Stdout = oldStdout
+			output2 := buf2.String()
+
+			// Verify status code
+			assert.Equal(t, http.StatusUnauthorized, resp2.Code, "Expected failed authentication")
+
+			// Check for log output based on verbose flag
+			if tt.expectLogs {
+				assert.Contains(t, output2, "Authentication failed", "Expected auth failure log when verbose=true")
+			} else {
+				assert.NotContains(t, output2, "Authentication failed", "Expected no auth failure log when verbose=false")
+			}
+		})
+	}
+}
+
+// TestAuthVerboseEnvironmentVariable tests that the environment variable is properly handled
+func TestAuthVerboseEnvironmentVariable(t *testing.T) {
+	tests := []struct {
+		name     string
+		envValue string
+		expected bool
+	}{
+		{
+			name:     "SERVICE_AUTH_VERBOSE=true",
+			envValue: "true",
+			expected: true,
+		},
+		{
+			name:     "SERVICE_AUTH_VERBOSE=false",
+			envValue: "false",
+			expected: false,
+		},
+		{
+			name:     "SERVICE_AUTH_VERBOSE empty",
+			envValue: "",
+			expected: false, // default value
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			// Clean up environment
+			os.Unsetenv("SERVICE_AUTH_VERBOSE")
+
+			if tt.envValue != "" {
+				os.Setenv("SERVICE_AUTH_VERBOSE", tt.envValue)
+				defer os.Unsetenv("SERVICE_AUTH_VERBOSE")
+			}
+
+			options := &models.Options{
+				AuthVerbose: false, // default
+			}
+
+			// Simulate what main.go does
+			if os.Getenv("SERVICE_AUTH_VERBOSE") != "" {
+				options.AuthVerbose = os.Getenv("SERVICE_AUTH_VERBOSE") == "true"
+			}
+
+			assert.Equal(t, tt.expected, options.AuthVerbose, "AuthVerbose should match expected value")
+		})
+	}
+}
+
+// TestNoAuthLogsInQuietMode verifies that with AuthVerbose=false, various auth scenarios don't produce logs
+func TestNoAuthLogsInQuietMode(t *testing.T) {
+	// This test demonstrates the fix for the bulk upload/crawler scenario
+	// Capture stdout
+	oldStdout := os.Stdout
+	r, w, _ := os.Pipe()
+	os.Stdout = w
+
+	options := &models.Options{
+		AuthVerbose: false, // Quiet mode
+		AdminKey:    "test-admin-key",
+	}
+
+	config := huma.DefaultConfig("Test API", "1.0.0")
+	router := http.NewServeMux()
+	api := humago.New(router, config)
+
+	api.UseMiddleware(auth.EmbAPIKeyAdminAuth(api, options))
+	api.UseMiddleware(auth.AuthTermination(api, options))
+
+	huma.Register(api, huma.Operation{
+		OperationID: "bulk-test",
+		Method:      http.MethodPost,
+		Path:        "/bulk",
+		Security: []map[string][]string{
+			{"adminAuth": {}},
+		},
+	}, func(ctx context.Context, input *struct{}) (*struct{}, error) {
+		return &struct{}{}, nil
+	})
+
+	// Simulate many requests (like bulk upload or crawler)
+	for i := 0; i < 50; i++ {
+		req := httptest.NewRequest(http.MethodPost, "/bulk", nil)
+		req.Header.Set("Authorization", "Bearer test-admin-key")
+		resp := httptest.NewRecorder()
+		router.ServeHTTP(resp, req)
+		assert.Equal(t, http.StatusNoContent, resp.Code)
+	}
+
+	// Capture output
+	w.Close()
+	var buf bytes.Buffer
+	io.Copy(&buf, r)
+	os.Stdout = oldStdout
+	output := buf.String()
+
+	// Count authentication success messages - should be 0 in quiet mode
+	count := strings.Count(output, "authentication successful")
+	assert.Equal(t, 0, count, "Expected no authentication logs in quiet mode during bulk operations")
+}