feat: add agent response logging

apps/freya-backend/src/agent/scheduler.ts

@@ -2,10 +2,19 @@ import type { UserEvent } from "@freya/agent-protocol"
 
 import type { ConversationStorage } from "../conversations/storage"
 import type { Job, JobRegistry } from "../lib/job"
+import type { AppLogger } from "../lib/logger"
 import type { AgentResponseJobPayload } from "./job"
 
 import { ConversationNotFoundError } from "../conversations/errors"
 import { ConversationResponseStateStatus } from "../db/schema"
+import { logger as rootLogger } from "../lib/logger"
+
+const AgentJobCancellationReason = {
+	NewUserActivity: "new_user_activity",
+	SupersededByEnqueue: "superseded_by_enqueue",
+} as const
+type AgentJobCancellationReason =
+	(typeof AgentJobCancellationReason)[keyof typeof AgentJobCancellationReason]
 
 interface AgentMessageSchedulerConfig {
 	storage: ConversationStorage
@@ -14,9 +23,10 @@ interface AgentMessageSchedulerConfig {
 	/**
 	 * How long to wait before responding to the user.
 	 */
-	waitTIme: number
+	waitTime: number
 
 	jobRegistry: JobRegistry<AgentResponseJobPayload>
+	logger?: AppLogger
 }
 
 /**
@@ -25,6 +35,7 @@ interface AgentMessageSchedulerConfig {
 export class AgentWorkScheduler {
 	private conversationStorage: ConversationStorage
 	private jobRegistry: JobRegistry<AgentResponseJobPayload>
+	private logger: AppLogger
 
 	private timing: {
 		maxWaitTime: number
@@ -37,9 +48,10 @@ export class AgentWorkScheduler {
 	constructor(config: AgentMessageSchedulerConfig) {
 		this.conversationStorage = config.storage
 		this.jobRegistry = config.jobRegistry
+		this.logger = config.logger ?? rootLogger.child({ component: "agent_scheduler" })
 		this.timing = {
 			maxWaitTime: config.maxWaitTime,
-			waitTime: config.waitTIme,
+			waitTime: config.waitTime,
 		}
 
 		this.jobRegistry.addEventListener("settled", this.eraseJob.bind(this))
@@ -50,9 +62,10 @@ export class AgentWorkScheduler {
 		const existing = this.timers.get(conversationId)
 		if (existing) {
 			clearTimeout(existing)
+			this.logger.debug({ conversationId }, "existing agent response timer replaced")
 		}
 
-		this.cancelCurrentJob(conversationId)
+		this.cancelCurrentJob(conversationId, AgentJobCancellationReason.NewUserActivity)
 
 		this.timers.set(
 			conversationId,
@@ -60,11 +73,22 @@ export class AgentWorkScheduler {
 				this.enqueueAgentResponse(conversationId)
 			}, this.timing.waitTime),
 		)
+
+		this.logger.info(
+			{
+				conversationId,
+				maxWaitMs: this.timing.maxWaitTime,
+				waitMs: this.timing.waitTime,
+			},
+			"agent response scheduled",
+		)
 	}
 
 	async receiveUserEvent(conversationId: string, event: UserEvent) {
 		if (event.type === "typing") {
+			this.logger.debug({ conversationId, eventType: event.type }, "user event received")
 			await this.delayAgentResponse(conversationId)
+			this.logger.debug({ conversationId }, "agent response delay handled")
 		}
 	}
 
@@ -73,18 +97,20 @@ export class AgentWorkScheduler {
 		if (existing) {
 			clearTimeout(existing)
 			this.timers.delete(conversationId)
+			this.logger.debug({ conversationId }, "agent response timer consumed")
 		}
 
-		this.cancelCurrentJob(conversationId)
+		this.cancelCurrentJob(conversationId, AgentJobCancellationReason.SupersededByEnqueue)
 
 		const job = this.jobRegistry.addJob({
 			payload: { conversationId },
 		})
 		this.runningJobs.set(conversationId, job)
+		this.logger.info({ conversationId, jobId: job.id }, "agent response job enqueued")
 	}
 
 	private async delayAgentResponse(conversationId: string) {
-		this.cancelCurrentJob(conversationId)
+		this.cancelCurrentJob(conversationId, AgentJobCancellationReason.NewUserActivity)
 
 		try {
 			const ok = await this.conversationStorage.transaction(async (storage) => {
@@ -102,14 +128,20 @@ export class AgentWorkScheduler {
 			})
 			if (ok) {
 				await this.scheduleAgentResponse(conversationId)
+			} else {
+				this.logger.debug(
+					{ conversationId },
+					"agent response delay skipped because response state is not pending",
+				)
 			}
 		} catch (error) {
 			if (error instanceof ConversationNotFoundError) {
 				// the user is typing but there isn't a scheduled agent response yet
 				// which means the user is typing their first message after the agent has previously responded
 				// swallow the error
+				this.logger.debug({ conversationId }, "typing event received without active conversation")
 			} else {
-				console.error("[agent response scheduler] error delaying agent response", error)
+				this.logger.error({ err: error, conversationId }, "agent response delay failed")
 			}
 			return
 		}
@@ -119,18 +151,26 @@ export class AgentWorkScheduler {
 	 * cancels the current job for agent response for the given conversation id
 	 * no-op if there is no active job for the conversation.
 	 */
-	private cancelCurrentJob(conversationId: string): void {
+	private cancelCurrentJob(conversationId: string, reason: AgentJobCancellationReason): void {
 		const job = this.runningJobs.get(conversationId)
 		if (!job) return
 
 		// If an active response is working on stale context, abort it so the next
 		// job can answer using the latest pending user messages.
 		this.jobRegistry.cancelJob(job)
+		this.logger.info(
+			{ conversationId, jobId: job.id, reason },
+			"active agent response job cancelled",
+		)
 	}
 
 	private eraseJob(job: Job<AgentResponseJobPayload>) {
 		if (this.runningJobs.get(job.payload.conversationId) === job) {
 			this.runningJobs.delete(job.payload.conversationId)
+			this.logger.debug(
+				{ conversationId: job.payload.conversationId, jobId: job.id },
+				"agent response job tracking cleared",
+			)
 		}
 	}
 }