fix(#338): Add structured logging for embedding failures

- Replace console.error with NestJS Logger
- Include entry ID and workspace ID in error context
- Easier to track and debug embedding issues

Refs #338

Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
This commit is contained in:
Jason Woltje
2026-02-05 16:26:30 -06:00
parent 6c88e2b96d
commit 7f3cd17488
2 changed files with 296 additions and 2 deletions

View File

@@ -0,0 +1,286 @@
import { describe, it, expect, beforeEach, vi } from "vitest";
import { Test, TestingModule } from "@nestjs/testing";
import { KnowledgeService } from "./knowledge.service";
import { PrismaService } from "../prisma/prisma.service";
import { LinkSyncService } from "./services/link-sync.service";
import { KnowledgeCacheService } from "./services/cache.service";
import { EmbeddingService } from "./services/embedding.service";
import { OllamaEmbeddingService } from "./services/ollama-embedding.service";
import { EmbeddingQueueService } from "./queues/embedding-queue.service";
describe("KnowledgeService - Embedding Error Logging", () => {
let service: KnowledgeService;
let mockEmbeddingQueueService: {
queueEmbeddingJob: ReturnType<typeof vi.fn>;
};
const workspaceId = "workspace-123";
const userId = "user-456";
const entryId = "entry-789";
const slug = "test-entry";
const mockCreatedEntry = {
id: entryId,
workspaceId,
slug,
title: "Test Entry",
content: "# Test Content",
contentHtml: "<h1>Test Content</h1>",
summary: "Test summary",
status: "DRAFT",
visibility: "PRIVATE",
createdAt: new Date("2026-01-01"),
updatedAt: new Date("2026-01-01"),
createdBy: userId,
updatedBy: userId,
tags: [],
};
const mockPrismaService = {
knowledgeEntry: {
findUnique: vi.fn(),
create: vi.fn(),
update: vi.fn(),
count: vi.fn(),
findMany: vi.fn(),
},
knowledgeEntryVersion: {
create: vi.fn(),
count: vi.fn(),
findMany: vi.fn(),
},
knowledgeEntryTag: {
deleteMany: vi.fn(),
},
knowledgeTag: {
findUnique: vi.fn(),
create: vi.fn(),
},
$transaction: vi.fn(),
};
const mockLinkSyncService = {
syncLinks: vi.fn().mockResolvedValue(undefined),
};
const mockCacheService = {
getEntry: vi.fn().mockResolvedValue(null),
setEntry: vi.fn().mockResolvedValue(undefined),
invalidateEntry: vi.fn().mockResolvedValue(undefined),
invalidateSearches: vi.fn().mockResolvedValue(undefined),
invalidateGraphs: vi.fn().mockResolvedValue(undefined),
invalidateGraphsForEntry: vi.fn().mockResolvedValue(undefined),
};
const mockEmbeddingService = {
isConfigured: vi.fn().mockReturnValue(false),
prepareContentForEmbedding: vi.fn().mockReturnValue("prepared content"),
batchGenerateEmbeddings: vi.fn().mockResolvedValue(0),
};
const mockOllamaEmbeddingService = {
isConfigured: vi.fn().mockResolvedValue(false),
prepareContentForEmbedding: vi.fn().mockReturnValue("prepared content"),
generateAndStoreEmbedding: vi.fn().mockResolvedValue(undefined),
};
beforeEach(async () => {
mockEmbeddingQueueService = {
queueEmbeddingJob: vi.fn(),
};
const module: TestingModule = await Test.createTestingModule({
providers: [
KnowledgeService,
{
provide: PrismaService,
useValue: mockPrismaService,
},
{
provide: LinkSyncService,
useValue: mockLinkSyncService,
},
{
provide: KnowledgeCacheService,
useValue: mockCacheService,
},
{
provide: EmbeddingService,
useValue: mockEmbeddingService,
},
{
provide: OllamaEmbeddingService,
useValue: mockOllamaEmbeddingService,
},
{
provide: EmbeddingQueueService,
useValue: mockEmbeddingQueueService,
},
],
}).compile();
service = module.get<KnowledgeService>(KnowledgeService);
vi.clearAllMocks();
});
describe("create - embedding failure logging", () => {
it("should log structured warning when embedding generation fails during create", async () => {
// Setup: transaction returns created entry
mockPrismaService.$transaction.mockResolvedValue(mockCreatedEntry);
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(null); // For slug uniqueness check
// Make embedding queue fail
const embeddingError = new Error("Ollama service unavailable");
mockEmbeddingQueueService.queueEmbeddingJob.mockRejectedValue(embeddingError);
// Spy on the logger
const loggerWarnSpy = vi.spyOn(service["logger"], "warn");
// Create entry
await service.create(workspaceId, userId, {
title: "Test Entry",
content: "# Test Content",
});
// Wait for async embedding generation to complete (and fail)
await new Promise((resolve) => setTimeout(resolve, 10));
// Verify structured logging was called
expect(loggerWarnSpy).toHaveBeenCalledWith(
expect.stringContaining("Failed to generate embedding for entry"),
expect.objectContaining({
entryId,
workspaceId,
error: "Ollama service unavailable",
})
);
});
it("should include entry ID and workspace ID in error context during create", async () => {
mockPrismaService.$transaction.mockResolvedValue(mockCreatedEntry);
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(null);
mockEmbeddingQueueService.queueEmbeddingJob.mockRejectedValue(
new Error("Connection timeout")
);
const loggerWarnSpy = vi.spyOn(service["logger"], "warn");
await service.create(workspaceId, userId, {
title: "Test Entry",
content: "# Test Content",
});
await new Promise((resolve) => setTimeout(resolve, 10));
// Verify the structured context contains required fields
const callArgs = loggerWarnSpy.mock.calls[0];
expect(callArgs[1]).toHaveProperty("entryId", entryId);
expect(callArgs[1]).toHaveProperty("workspaceId", workspaceId);
expect(callArgs[1]).toHaveProperty("error", "Connection timeout");
});
it("should handle non-Error objects in embedding failure during create", async () => {
mockPrismaService.$transaction.mockResolvedValue(mockCreatedEntry);
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(null);
// Reject with a string instead of Error
mockEmbeddingQueueService.queueEmbeddingJob.mockRejectedValue("String error message");
const loggerWarnSpy = vi.spyOn(service["logger"], "warn");
await service.create(workspaceId, userId, {
title: "Test Entry",
content: "# Test Content",
});
await new Promise((resolve) => setTimeout(resolve, 10));
// Should convert non-Error to string
expect(loggerWarnSpy).toHaveBeenCalledWith(
expect.any(String),
expect.objectContaining({
error: "String error message",
})
);
});
});
describe("update - embedding failure logging", () => {
const existingEntry = {
...mockCreatedEntry,
versions: [{ version: 1 }],
};
const updatedEntry = {
...mockCreatedEntry,
title: "Updated Title",
content: "# Updated Content",
};
it("should log structured warning when embedding generation fails during update", async () => {
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(existingEntry);
mockPrismaService.$transaction.mockResolvedValue(updatedEntry);
const embeddingError = new Error("Embedding model not loaded");
mockEmbeddingQueueService.queueEmbeddingJob.mockRejectedValue(embeddingError);
const loggerWarnSpy = vi.spyOn(service["logger"], "warn");
await service.update(workspaceId, slug, userId, {
content: "# Updated Content",
});
await new Promise((resolve) => setTimeout(resolve, 10));
expect(loggerWarnSpy).toHaveBeenCalledWith(
expect.stringContaining("Failed to generate embedding for entry"),
expect.objectContaining({
entryId,
workspaceId,
error: "Embedding model not loaded",
})
);
});
it("should include entry ID and workspace ID in error context during update", async () => {
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(existingEntry);
mockPrismaService.$transaction.mockResolvedValue(updatedEntry);
mockEmbeddingQueueService.queueEmbeddingJob.mockRejectedValue(
new Error("Rate limit exceeded")
);
const loggerWarnSpy = vi.spyOn(service["logger"], "warn");
await service.update(workspaceId, slug, userId, {
title: "New Title",
});
await new Promise((resolve) => setTimeout(resolve, 10));
const callArgs = loggerWarnSpy.mock.calls[0];
expect(callArgs[1]).toHaveProperty("entryId", entryId);
expect(callArgs[1]).toHaveProperty("workspaceId", workspaceId);
expect(callArgs[1]).toHaveProperty("error", "Rate limit exceeded");
});
it("should not trigger embedding generation if only status is updated", async () => {
mockPrismaService.knowledgeEntry.findUnique.mockResolvedValue(existingEntry);
mockPrismaService.$transaction.mockResolvedValue({
...existingEntry,
status: "PUBLISHED",
});
await service.update(workspaceId, slug, userId, {
status: "PUBLISHED",
});
await new Promise((resolve) => setTimeout(resolve, 10));
// Embedding should not be called when only status changes
expect(mockEmbeddingQueueService.queueEmbeddingJob).not.toHaveBeenCalled();
});
});
});

View File

@@ -244,7 +244,11 @@ export class KnowledgeService {
// Generate and store embedding asynchronously (don't block the response)
this.generateEntryEmbedding(result.id, result.title, result.content).catch((error: unknown) => {
console.error(`Failed to generate embedding for entry ${result.id}:`, error);
this.logger.warn(`Failed to generate embedding for entry - embedding will be missing`, {
entryId: result.id,
workspaceId,
error: error instanceof Error ? error.message : String(error),
});
});
// Invalidate search and graph caches (new entry affects search results)
@@ -407,7 +411,11 @@ export class KnowledgeService {
if (updateDto.content !== undefined || updateDto.title !== undefined) {
this.generateEntryEmbedding(result.id, result.title, result.content).catch(
(error: unknown) => {
console.error(`Failed to generate embedding for entry ${result.id}:`, error);
this.logger.warn(`Failed to generate embedding for entry - embedding will be missing`, {
entryId: result.id,
workspaceId,
error: error instanceof Error ? error.message : String(error),
});
}
);
}