feat: use winston for logging

Signed-off-by: chilir <[email protected]>

Author: chilir

.dockerignore

@@ -4,6 +4,7 @@
 docs
 example
 img
+logs
 node_modules
 result
 .editorconfig

README.md

@@ -71,6 +71,7 @@ services:
       - ./.env # required
     volumes:
       - ./config.yaml:/app/config.yaml:ro # required
+      - ./logs:/app/logs:rw # will be created if not present
       - ./.sqlite:/app/.sqlite:rw  # will be created if not present
 
     # if you're hosting the model service on the same machine:

example/.gitignore

@@ -1 +1,2 @@
-.example_output
+.example_output
+example_logs

example/compose.yaml

@@ -4,12 +4,14 @@
 
 services:
   app:
-    image: ghcr.io/chilir/chat-thyme:nightly
+    # image: ghcr.io/chilir/chat-thyme:nightly
+    image: chat-thyme:test-debug
     command: [ "-c", "/app/config.yaml" ]
     env_file:
       - ../.env
     volumes:
       - ./config.yaml:/app/config.yaml:ro
+      - ./example_logs:/app/logs:rw
       - ./.example_output:/app/.sqlite:rw
 
     # if you're hosting the model service on the same machine:

src/backend/chat.ts

@@ -3,6 +3,7 @@
 import type { Database } from "bun:sqlite";
 import type Exa from "exa-js";
 import type OpenAI from "openai";
+import winston from "winston";
 import { getOrInitUserDb, releaseUserDb } from "../db/sqlite";
 import type {
   ChatThreadInfo,
@@ -52,7 +53,7 @@ export const extractChoiceContent = async (
   chatId: string,
 ): Promise<ProcessedMessageContent> => {
   if (!choices.length) {
-    console.warn("Received empty choices array in model response");
+    winston.warn("Received empty choices array in model response");
     return {
       timestamp: timestamp,
       msgContent: "No response was generated",
@@ -177,9 +178,9 @@ export const processUserMessage = async (
       systemPrompt,
     );
 
-    console.debug("\n----------");
-    console.debug("Current chat messages from DB:");
-    console.debug(currentChatMessages);
+    winston.debug("\n----------");
+    winston.debug("Current chat messages from DB:");
+    winston.debug(JSON.stringify(currentChatMessages, null, 2));
 
     currentChatMessages.push({ role: "user", content: discordMessageContent });
 
@@ -211,12 +212,12 @@ export const processUserMessage = async (
       extractedChoiceContent.reasoningContent,
     );
 
-    console.debug("\n----------");
-    console.debug("Current chat messages:");
-    console.debug(currentChatMessages);
-    console.debug("\n----------");
-    console.debug("Response from model:");
-    console.debug(formattedModelResponse);
+    winston.debug("\n----------");
+    winston.debug("Current chat messages:");
+    winston.debug(JSON.stringify(currentChatMessages, null, 2));
+    winston.debug("\n----------");
+    winston.debug("Response from model:");
+    winston.debug(JSON.stringify(formattedModelResponse, null, 2));
 
     currentChatMessages.push({
       role: "assistant",
@@ -240,7 +241,7 @@ export const processUserMessage = async (
       null,
     );
   } catch (error) {
-    console.error(
+    winston.error(
       `Error processing user message for ${chatThreadInfo.userId} in chat \
 ${chatThreadInfo.chatId}:`,
       error,

src/backend/llm-service.ts

@@ -2,6 +2,7 @@
 
 import { APIError, type OpenAI } from "openai";
 import pRetry from "p-retry";
+import winston from "winston";
 import type {
   ChatPrompt,
   ExpandedChatParameters,
@@ -30,11 +31,11 @@ export const chatWithModel = async (
   prompt: ChatPrompt,
   options: Partial<ExpandedChatParameters>,
 ): Promise<OpenAI.Chat.ChatCompletion> => {
-  console.debug("\n----------");
-  console.debug("Debug input:");
-  console.debug(prompt.messages);
-  console.debug(prompt.messages[0]?.content);
-  console.debug(options);
+  winston.debug("\n----------");
+  winston.debug("Debug input:");
+  winston.debug(JSON.stringify(prompt.messages, null, 2));
+  winston.debug(JSON.stringify(prompt.messages[0]?.content, null, 2));
+  winston.debug(JSON.stringify(options, null, 2));
 
   try {
     const response = await pRetry(
@@ -51,17 +52,17 @@ export const chatWithModel = async (
               messages: prompt.messages,
               ...options,
             };
-        console.debug("\n----------");
-        console.debug("Debug body:");
-        console.debug(chatBody);
+        winston.debug("\n----------");
+        winston.debug("Debug body:");
+        winston.debug(JSON.stringify(chatBody, null, 2));
         const chatResponse = (await modelClient.chat.completions.create(
           chatBody,
         )) as ExpandedChatResponse;
 
         if (chatResponse.error) {
-          console.debug("\n----------");
-          console.debug("Error as part of model response object:");
-          console.debug(chatResponse.error);
+          winston.debug("\n----------");
+          winston.debug("Error as part of model response object:");
+          winston.debug(JSON.stringify(chatResponse.error, null, 2));
 
           throw new APIError(
             chatResponse.error.code,
@@ -89,14 +90,14 @@ export const chatWithModel = async (
             );
           }
 
-          console.debug("\n----------");
-          console.debug("Error that is not `APIError`:");
-          console.debug(error);
+          winston.debug("\n----------");
+          winston.debug("Error that is not `APIError`:");
+          winston.debug(JSON.stringify(error, null, 2));
 
           return true; // retry unknown errors
         },
         onFailedAttempt: (error) => {
-          console.debug(
+          winston.debug(
             `Chat response attempt ${error.attemptNumber} failed. There are \
 ${error.retriesLeft} retries left...`,
           );
@@ -116,12 +117,12 @@ ${error.retriesLeft} retries left...`,
       errorMsg = error instanceof Error ? error.message : `${error}`;
     }
 
-    console.debug("\n----------");
-    console.debug(error);
-    console.debug(`Model response error code: ${errorCode}`);
-    console.debug(`Model response error message: ${errorMsg}`);
-    console.debug("Model response error metadata:");
-    console.debug(errorMetadata);
+    winston.debug("\n----------");
+    winston.debug(JSON.stringify(error, null, 2));
+    winston.debug(`Model response error code: ${errorCode}`);
+    winston.debug(`Model response error message: ${errorMsg}`);
+    winston.debug("Model response error metadata:");
+    winston.debug(JSON.stringify(errorMetadata, null, 2));
 
     if (!errorCode) {
       throw new Error(

src/backend/tools.ts

@@ -16,6 +16,7 @@ import {
   processOpenRouterContent,
   saveChatMessageToDb,
 } from "./utils";
+import winston from "winston";
 
 /**
  * Processes an Exa search tool call and returns the search results.
@@ -48,20 +49,20 @@ const processExaSearchCall = async (
       maxTimeout: 60000,
       // TODO: use `shouldRetry` to not retry on 402s (insufficient balance)
       onFailedAttempt: (error) => {
-        console.warn(
+        winston.warn(
           `Search attempt ${error.attemptNumber} failed. ${error.retriesLeft} \
 retries left.`,
         );
       },
     },
   ).catch((error) => {
-    console.error("Search failed after all retries:", error);
+    winston.error("Search failed after all retries:", error);
     return null;
   });
 
-  console.debug("\n----------");
-  console.debug("Exa search results:");
-  console.debug(searchResults);
+  winston.debug("\n----------");
+  winston.debug("Exa search results:");
+  winston.debug(JSON.stringify(searchResults, null, 2));
 
   return {
     role: "tool",
@@ -118,9 +119,9 @@ export const processToolCalls = async (
   userId: string,
   chatId: string,
 ): Promise<ProcessedMessageContent> => {
-  console.debug("\n----------");
-  console.debug("Tool calls:");
-  console.debug(toolCalls);
+  winston.debug("\n----------");
+  winston.debug("Tool calls:");
+  winston.debug(JSON.stringify(toolCalls, null, 2));
 
   for (const toolCall of toolCalls) {
     if (toolCall.function.name === "exa_search") {
@@ -136,7 +137,7 @@ export const processToolCalls = async (
         toolResponse.tool_call_id,
       );
     } else {
-      console.warn(`Unknown tool call: ${toolCall.function.name}`);
+      winston.warn(`Unknown tool call: ${toolCall.function.name}`);
     }
   }
 
@@ -171,7 +172,7 @@ export const processToolCalls = async (
   }
 
   if (!responseToToolCallResults.choices.length) {
-    console.warn(
+    winston.warn(
       "Received empty choices array in model response for tool call results",
     );
     return {

src/backend/utils.test.ts

@@ -4,6 +4,7 @@ import { Database } from "bun:sqlite";
 import { afterEach, beforeEach, describe, expect, it } from "bun:test";
 import type OpenAI from "openai";
 import tmp from "tmp";
+import winston from "winston";
 import type {
   DbChatMessageToSave,
   ExpandedChatCompletionMessage,
@@ -18,6 +19,27 @@ import {
 } from "./utils";
 
 tmp.setGracefulCleanup();
+const errorPrintfFormat = winston.format.printf(
+  ({ level, message, timestamp, stack, ...metadata }) => {
+    let logMsg = `[${timestamp}] ${level}: ${message}`;
+    if (stack) {
+      logMsg += `\nStack trace:\n${stack}`; // Add stack trace if available
+    }
+    if (Object.keys(metadata).length > 0) {
+      logMsg += `\nMetadata: ${JSON.stringify(metadata, null, 2)}`; // Add metadata as JSON
+    }
+    return logMsg;
+  },
+);
+winston.add(
+  new winston.transports.Console({
+    format: winston.format.combine(
+      winston.format.timestamp({ format: "YYYY-MM-DD HH:mm:ss.SSS" }),
+      winston.format.colorize(),
+      errorPrintfFormat, // Use the new format
+    ),
+  }),
+);
 
 const systemRole = "system";
 const testSystemPrompt = "You are a helpful assistant.";

src/backend/utils.ts

@@ -2,6 +2,7 @@
 
 import type { Database } from "bun:sqlite";
 import type OpenAI from "openai";
+import winston from "winston";
 import type {
   DbChatMessageToSave,
   ExpandedChatCompletionMessage,
@@ -31,7 +32,7 @@ export const parseDbRow = (
         row.content as string,
       ) as OpenAI.ChatCompletionContentPart[];
     } catch (error) {
-      console.error(
+      winston.error(
         `Error parsing tool call (id: ${row.tool_call_id}) content from \
 database. Raw JSON string: ${row.content}:`,
         error,
@@ -53,7 +54,7 @@ database. Raw JSON string: ${row.content}:`,
         row.tool_calls as string,
       ) as OpenAI.ChatCompletionMessageToolCall[];
     } catch (error) {
-      console.error(
+      winston.error(
         `Error parsing tool calls from database. Raw JSON string: \
 ${row.tool_calls}:`,
         error,
@@ -105,7 +106,7 @@ export const getChatHistoryFromDb = async (
         .all(chatId) as DbChatMessageToSave[]
     ).map(parseDbRow) as OpenAI.ChatCompletionMessageParam[];
   } catch (error) {
-    console.error(
+    winston.error(
       `Error getting chat history from database for ${userId} in chat \
 ${chatId}:`,
       error,
@@ -251,7 +252,7 @@ export const saveChatMessageToDb = async (
       ],
     );
   } catch (error) {
-    console.error(
+    winston.error(
       `Error saving chat message to database for ${userId} in chat ${chatId}:`,
       error,
     );

src/config/parse.test.ts

@@ -4,11 +4,33 @@ import { beforeEach, describe, expect, it } from "bun:test";
 import fs from "node:fs";
 import path from "node:path";
 import tmp from "tmp";
+import winston from "winston";
 import { ZodError } from "zod";
 import { parseConfig } from "./parse";
 import { defaultAppConfig } from "./schema";
 
 tmp.setGracefulCleanup();
+const errorPrintfFormat = winston.format.printf(
+  ({ level, message, timestamp, stack, ...metadata }) => {
+    let logMsg = `[${timestamp}] ${level}: ${message}`;
+    if (stack) {
+      logMsg += `\nStack trace:\n${stack}`; // Add stack trace if available
+    }
+    if (Object.keys(metadata).length > 0) {
+      logMsg += `\nMetadata: ${JSON.stringify(metadata, null, 2)}`; // Add metadata as JSON
+    }
+    return logMsg;
+  },
+);
+winston.add(
+  new winston.transports.Console({
+    format: winston.format.combine(
+      winston.format.timestamp({ format: "YYYY-MM-DD HH:mm:ss.SSS" }),
+      winston.format.colorize(),
+      errorPrintfFormat
+    ),
+  }),
+);
 
 describe("Configuration Parsing and Loading", () => {
   const originalEnv = { ...process.env };