Route request-path logs through the context logger

agent-manager-service/.github/linters/.golangci.yaml

@@ -8,17 +8,35 @@ linters:
   enable:
     - errorlint
     - exhaustruct
+    - forbidigo
     - goheader
     - grouper
     - nilerr
     - nilnil
     - nolintlint
     - reassign
+    - sloglint
     - wastedassign
   disable:
     - revive
     - unused
   settings:
+    # Only the context logger carries the correlation ID, so a package-level
+    # slog call on a request path emits a line that cannot be tied back to the
+    # request that produced it. Startup, shutdown and migrations have no
+    # request and are excluded below.
+    forbidigo:
+      forbid:
+        - pattern: ^slog\.(Info|Warn|Error|Debug)(Context)?$
+          msg: use logger.GetLogger(ctx) so the record carries the correlation ID (see docs/logging.md)
+      # Matched on the source expression: `slog.Info` is a package-level
+      # function, not a method on a type forbidigo could resolve.
+      analyze-types: false
+    sloglint:
+      # Catches the alternating key/value form being broken — a bare value in a
+      # key position serialises as "!BADKEY" and the record loses the field.
+      no-mixed-args: true
+      key-naming-case: snake
     exhaustruct:
       include:
         - .*\.Test
@@ -53,6 +71,25 @@ linters:
       - linters:
           - exhaustruct
         path: \_test.go
+      # No request context exists during startup, shutdown or migrations.
+      - linters:
+          - forbidigo
+        path: (app|config|db|server|db_migrations)/
+      # These repository methods predate the context convention and take no
+      # context.Context, so their logs cannot reach the request logger. Give
+      # them the exemption rather than deleting logs that already exist;
+      # threading a context through the repository interface (and its generated
+      # mock) is a change worth making on its own terms.
+      - linters:
+          - forbidigo
+        path: repositories/llm_provider_repository\.go
+      - linters:
+          - forbidigo
+        path: main\.go
+      - linters:
+          - forbidigo
+          - sloglint
+        path: \_test.go
     paths:
       - agent-manager-service/spec
       - third_party$

agent-manager-service/AGENTS.md

@@ -109,7 +109,7 @@ Generated files are checked in and **never hand-edited**. Regenerate and commit
 - **Tenant isolation is DB-only** — org isolation happens at the DB (`ou_id`) layer alone. All OpenChoreo API calls resolve to a single default namespace from config (`OPEN_CHOREO_DEFAULT_NAMESPACE`, default `"default"`, `config.OpenChoreo.DefaultNamespace`), so there is no namespace-level tenant separation yet.
 - **Concurrency** — never hold a lock across I/O. Atomic upserts (`ON CONFLICT`), not read-then-write. Serialize expensive side effects per-key, not globally.
 - **Config** — validate at startup, not first use; check co-dependent values together.
-- **Observability** — log with correlation context (org, resource ID, request ID). Debug = hot paths, Info = rare events, Error = destructive ops.
+- **Observability** — get the logger from the context (`logger.GetLogger(ctx)`), never the package-level `slog` functions: only the context logger carries the correlation ID, and CI rejects `slog.Info/Warn/Error/Debug` outside `app/`, `db/` and `server/`. Keys are snake_case and one concept has one name (`ou_id`, `error`, `duration_ms`); untrusted values go through `utils.SanitizeForLog`. `Error` = the service failed, `Warn` = handled, including every 4xx, `Info` = rare state change, `Debug` = hot path. Log a failure **once, at the boundary** — the controller's `log.Error` already prints the whole `%w` chain, so a service that logs and re-returns logs at `Warn`. See `docs/logging.md`.
 
 # Testing
 

agent-manager-service/api/app.go

@@ -120,10 +120,14 @@ func MakeHTTPHandler(params *wiring.AppParams, extraAPIRoutes func(*http.ServeMu
 	// Apply middleware in reverse order (last middleware is applied first)
 	apiHandler := http.Handler(apiMux)
 	apiHandler = params.AuthMiddleware(apiHandler)
+	// Applied innermost-first. RecovererOnPanic sits *inside* AddCorrelationID
+	// and RequestLogger so the record it writes carries the correlation ID and
+	// the request line; outside them it could only ever log "unknown". The
+	// three middleware now outside it do no caller-driven work.
+	apiHandler = middleware.RecovererOnPanic()(apiHandler)
 	apiHandler = logger.RequestLogger()(apiHandler)
 	apiHandler = middleware.AddCorrelationID()(apiHandler)
 	apiHandler = middleware.CORS(config.GetConfig().CORSAllowedOrigin)(apiHandler)
-	apiHandler = middleware.RecovererOnPanic()(apiHandler)
 
 	mux.Handle("/api/v1/", http.StripPrefix("/api/v1", apiHandler))
 
@@ -157,10 +161,10 @@ func MakeInternalHTTPHandler(params *wiring.AppParams) http.Handler {
 	// handler-level emits for api-key rejections, which happen before any route
 	// wrapper could see them.
 	internalHandler = middleware.WithAuditRecorder(params.AuditRecorder, audit.SurfaceInternal)(internalHandler)
+	internalHandler = middleware.RecovererOnPanic()(internalHandler)
 	internalHandler = logger.RequestLogger()(internalHandler)
 	internalHandler = middleware.AddCorrelationID()(internalHandler)
 	internalHandler = middleware.CORS(config.GetConfig().CORSAllowedOrigin)(internalHandler)
-	internalHandler = middleware.RecovererOnPanic()(internalHandler)
 
 	mux.Handle("/api/internal/v1/", http.StripPrefix("/api/internal/v1", internalHandler))
 

agent-manager-service/app/app.go

@@ -27,6 +27,8 @@ import (
 	"log/slog"
 	"net/http"
 	"os"
+	"strconv"
+	"strings"
 	"sync"
 	"time"
 
@@ -41,6 +43,7 @@ import (
 	"github.com/wso2/agent-manager/agent-manager-service/server"
 	"github.com/wso2/agent-manager/agent-manager-service/services"
 	"github.com/wso2/agent-manager/agent-manager-service/signals"
+	"github.com/wso2/agent-manager/agent-manager-service/utils"
 	"github.com/wso2/agent-manager/agent-manager-service/wiring"
 
 	"go.uber.org/automaxprocs/maxprocs"
@@ -310,10 +313,10 @@ func Run(authProvider occlient.AuthProvider, secretProvider secretmanagersvc.Pro
 		}
 		slog.Info("Internal server is running",
 			"address", fmt.Sprintf("%s://localhost:%d", scheme, cfg.InternalServer.Port),
-			"tlsEnabled", cfg.InternalServer.TLSEnabled,
-			"maxWebSocketConnections", cfg.WebSocket.MaxConnections,
-			"heartbeatTimeout", fmt.Sprintf("%ds", cfg.WebSocket.ConnectionTimeout),
-			"rateLimitPerMin", cfg.WebSocket.RateLimitPerMin)
+			"tls_enabled", cfg.InternalServer.TLSEnabled,
+			"max_web_socket_connections", cfg.WebSocket.MaxConnections,
+			"heartbeat_timeout", fmt.Sprintf("%ds", cfg.WebSocket.ConnectionTimeout),
+			"rate_limit_per_min", cfg.WebSocket.RateLimitPerMin)
 		if err := internalServer.Start(); err != nil && !errors.Is(err, http.ErrServerClosed) {
 			slog.Error("Failed to start internal server", "error", err)
 			os.Exit(1)
@@ -374,9 +377,45 @@ func recordStartupPosture(cfg *config.Config, recorder audit.Recorder) {
 	}
 }
 
+// compactSource rewrites slog's source group into a single "file:line" string.
+//
+// The default shape costs about 150 bytes on every record:
+//
+//	"source":{"function":"github.com/wso2/…/services.(*infraResourceManager).ListOrgDeploymentPipelines",
+//	          "file":"/app/services/infra_resource_manager.go","line":360}
+//
+// The function name repeats what the file already says, and the absolute path
+// is the build directory, which differs between the container and a local run.
+// What a reader actually needs is where to open the editor:
+//
+//	"source":"services/infra_resource_manager.go:360"
+//
+// The last two path segments are kept because that is the package-relative form
+// in this layout; a bare basename would be ambiguous across packages.
+func compactSource(_ []string, a slog.Attr) slog.Attr {
+	if a.Key != slog.SourceKey {
+		return a
+	}
+	src, ok := a.Value.Any().(*slog.Source)
+	if !ok || src == nil {
+		return a
+	}
+	file := src.File
+	if i := strings.LastIndex(file, "/"); i >= 0 {
+		if j := strings.LastIndex(file[:i], "/"); j >= 0 {
+			file = file[j+1:]
+		}
+	}
+	return slog.String(slog.SourceKey, file+":"+strconv.Itoa(src.Line))
+}
+
 func setupLogger(cfg *config.Config) {
+	// Normalised before matching: a lowercase LOG_LEVEL=debug used to fall
+	// through to INFO silently, so the setting appeared to have no effect.
+	configured := strings.ToUpper(strings.TrimSpace(cfg.LogLevel))
 	var level slog.Level
-	switch cfg.LogLevel {
+	recognised := true
+	switch configured {
 	case "DEBUG":
 		level = slog.LevelDebug
 	case "INFO":
@@ -387,18 +426,31 @@ func setupLogger(cfg *config.Config) {
 		level = slog.LevelError
 	default:
 		level = slog.LevelInfo // default to INFO
+		recognised = false
 	}
 
 	// Create handler options
 	opts := &slog.HandlerOptions{
 		Level: level,
+		// Records carry file:line, so a message no longer has to name its own
+		// call site to be locatable. ReplaceAttr collapses it — see compactSource.
+		AddSource:   true,
+		ReplaceAttr: compactSource,
 	}
 	handler := slog.NewJSONHandler(os.Stdout, opts)
 	logger := slog.New(handler)
 	slog.SetDefault(logger)
 
+	// The configured value is logged next to the resolved one so a typo is
+	// visible at startup rather than as unexplained missing output later.
 	slog.Info("Logger configured",
-		"level", level.String())
+		"level", level.String(),
+		"configured_level", utils.SanitizeForLog(cfg.LogLevel))
+	if !recognised && strings.TrimSpace(cfg.LogLevel) != "" {
+		slog.Warn("LOG_LEVEL not recognised; defaulting to INFO",
+			"configured_level", utils.SanitizeForLog(cfg.LogLevel),
+			"supported", []string{"DEBUG", "INFO", "WARN", "ERROR"})
+	}
 }
 
 // loadBuiltInLLMTemplates loads built-in LLM provider templates into in-memory store

agent-manager-service/audit/recorder.go

@@ -228,8 +228,8 @@ func (r *bufferedRecorder) noteDrop(e Event) {
 	}
 	r.logger.Error("audit buffer full; event dropped",
 		"action", string(e.Action),
-		"actorId", e.ActorID,
-		"droppedTotal", total,
+		"actor_id", e.ActorID,
+		"dropped_total", total,
 		"sink", r.sink.Name())
 }
 
@@ -290,6 +290,7 @@ func (u *uninstalledRecorder) warn(action Action) {
 	if u.warned.Swap(true) {
 		return
 	}
+	//nolint:forbidigo // reports a missing recorder, so the context it was handed cannot be trusted to carry a logger either
 	slog.Error("audit recorder not installed on context; events are being lost",
 		"action", string(action),
 		"hint", "install one with audit.WithRecorder in the surface's middleware")

agent-manager-service/clients/openchoreosvc/auth/auth.go

@@ -30,6 +30,7 @@ import (
 
 	"github.com/wso2/agent-manager/agent-manager-service/clients/openchoreosvc/client"
 	"github.com/wso2/agent-manager/agent-manager-service/clients/requests"
+	"github.com/wso2/agent-manager/agent-manager-service/middleware/logger"
 )
 
 // Compile-time check that AuthProvider implements client.AuthProvider
@@ -98,20 +99,20 @@ func (p *AuthProvider) GetToken(ctx context.Context) (string, error) {
 		return p.accessToken, nil
 	}
 
-	slog.Debug("openchoreo auth: fetching new token")
+	logger.GetLogger(ctx).Debug("openchoreo auth: fetching new token")
 
 	// Fetch new token
 	token, expiresIn, err := p.fetchToken(ctx)
 	if err != nil {
-		slog.Error("openchoreo auth: failed to fetch token", "error", err)
+		logger.GetLogger(ctx).Error("openchoreo auth: failed to fetch token", "error", err)
 		return "", fmt.Errorf("failed to fetch token: %w", err)
 	}
 
 	// Cache the token with expiry
 	p.accessToken = token
 	p.expiresAt = time.Now().Add(time.Duration(expiresIn) * time.Second)
 
-	slog.Info("openchoreo auth: fetched new access token",
+	logger.GetLogger(ctx).Info("openchoreo auth: fetched new access token",
 		"expires_at", p.expiresAt.Format(time.RFC3339))
 
 	return p.accessToken, nil
@@ -121,6 +122,7 @@ func (p *AuthProvider) GetToken(ctx context.Context) (string, error) {
 func (p *AuthProvider) InvalidateToken() {
 	p.mu.Lock()
 	defer p.mu.Unlock()
+	//nolint:forbidigo // process-wide token cache, shared across requests
 	slog.Debug("openchoreo auth: invalidating cached token")
 	p.accessToken = ""
 	p.expiresAt = time.Time{}
@@ -129,10 +131,12 @@ func (p *AuthProvider) InvalidateToken() {
 // isTokenValid checks if the cached token is still valid
 func (p *AuthProvider) isTokenValid() bool {
 	if p.accessToken == "" {
+		//nolint:forbidigo // process-wide token cache, shared across requests
 		slog.Debug("openchoreo auth: no cached token")
 		return false
 	}
 	isValid := time.Now().Add(expiryBuffer).Before(p.expiresAt)
+	//nolint:forbidigo // process-wide token cache, shared across requests
 	slog.Debug("openchoreo auth: token validation check",
 		"is_valid", isValid,
 		"expires_at", p.expiresAt.Format(time.RFC3339))

agent-manager-service/clients/openchoreosvc/client/authz.go

@@ -88,7 +88,7 @@ func (c *openChoreoClient) EnsureClusterRoleBinding(ctx context.Context, clientI
 			return fmt.Errorf("failed to update ClusterAuthzRoleBinding for %s: %w", clientID, err)
 		}
 		if updateResp.StatusCode() != http.StatusOK {
-			return handleErrorResponse(updateResp.StatusCode(), ErrorResponses{
+			return handleErrorResponse(ctx, updateResp.StatusCode(), ErrorResponses{
 				JSON400: updateResp.JSON400,
 				JSON401: updateResp.JSON401,
 				JSON403: updateResp.JSON403,
@@ -97,7 +97,7 @@ func (c *openChoreoClient) EnsureClusterRoleBinding(ctx context.Context, clientI
 		}
 		return nil
 	default:
-		return handleErrorResponse(resp.StatusCode(), ErrorResponses{
+		return handleErrorResponse(ctx, resp.StatusCode(), ErrorResponses{
 			JSON400: resp.JSON400,
 			JSON401: resp.JSON401,
 			JSON403: resp.JSON403,