From 674c3cbd44f21271f654ada1fc95f4edf29506c8 Mon Sep 17 00:00:00 2001 From: Danil Nikolaev Date: Wed, 13 May 2026 12:05:55 +0300 Subject: [PATCH] shitton --- src/ai/ai-logger.ts | 284 +----------------------- src/ai/provider-request-queue.ts | 14 +- src/ai/telegram-attachments.ts | 36 ++- src/ai/tools/brave-search.ts | 8 +- src/ai/tools/create-note.ts | 8 +- src/ai/tools/list-notes.ts | 23 +- src/ai/tools/market-rates.ts | 8 +- src/ai/tools/python-interpretator.ts | 28 ++- src/ai/tools/runtime.ts | 12 +- src/ai/tools/search-notes.ts | 7 +- src/ai/tools/send-note-file.ts | 7 +- src/ai/tools/utils.ts | 11 +- src/ai/tools/weather.ts | 13 +- src/ai/unified-ai-runner.gemini.ts | 2 +- src/ai/unified-ai-runner.mistral.ts | 2 +- src/ai/unified-ai-runner.ollama.ts | 2 +- src/ai/unified-ai-runner.openai.ts | 8 +- src/ai/unified-ai-runner.shared.ts | 14 +- src/ai/unified-ai-runner.tool-ranker.ts | 2 +- src/ai/unified-ai-runner.ts | 2 +- src/commands/choice.ts | 5 +- src/commands/gemini-get-model.ts | 20 +- src/commands/gemini-list-models.ts | 33 +-- src/commands/gemini-set-model.ts | 34 +-- src/commands/mistral-get-model.ts | 20 +- src/commands/mistral-list-models.ts | 33 +-- src/commands/mistral-set-model.ts | 34 +-- src/commands/ollama-get-model.ts | 20 +- src/commands/ollama-list-models.ts | 38 +--- src/commands/ollama-set-model.ts | 34 +-- src/commands/openai-get-model.ts | 20 +- src/commands/openai-list-models.ts | 33 +-- src/commands/openai-set-model.ts | 34 +-- src/commands/quote.ts | 16 +- src/common/environment.ts | 3 +- src/common/localization.ts | 8 +- src/db/message-dao.ts | 11 +- src/db/user-dao.ts | 11 +- src/index.ts | 24 +- src/util/files.ts | 12 +- src/util/shell-command-runner.ts | 9 +- src/util/telegram-api-queue.ts | 30 ++- src/util/utils.ts | 48 ++-- 43 files changed, 382 insertions(+), 639 deletions(-) diff --git a/src/ai/ai-logger.ts b/src/ai/ai-logger.ts index 52d4e3b..69d7958 100644 --- a/src/ai/ai-logger.ts +++ b/src/ai/ai-logger.ts @@ -1,283 +1 @@ -import {Message} from "typescript-telegram-bot-api"; - -export type AiRunnerLogLevel = "trace" | "debug" | "info" | "success" | "warn" | "error"; - -export type AiRunnerLogDetails = Record; - -export type AiLogToolCallLike = { - id: string; - name: string; - argumentsText: string; -}; - -const AI_RUNNER_LOG_PREFIX = "unified-ai-runner"; -const AI_RUNNER_LOG_MAX_STRING = 600; -const AI_RUNNER_LOG_MAX_ARRAY = 8; - -const LOG_LEVEL_WEIGHT: Record = { - trace: 10, - debug: 20, - info: 30, - success: 30, - warn: 40, - error: 50, -}; - -const AI_RUNNER_LOG_COLORS: Record = { - reset: "\x1b[0m", - bold: "\x1b[1m", - dim: "\x1b[2m", - trace: "\x1b[90m", - debug: "\x1b[90m", - info: "\x1b[36m", - success: "\x1b[32m", - warn: "\x1b[33m", - error: "\x1b[31m", - label: "\x1b[35m", - key: "\x1b[94m", - value: "\x1b[97m", -}; - -function envBool(name: string, defaultValue: boolean): boolean { - const value = process.env[name]; - if (value === undefined) return defaultValue; - return !["0", "false", "no", "off"].includes(value.trim().toLowerCase()); -} - -function aiRunnerLogsEnabled(): boolean { - return envBool("AI_RUNNER_LOGS", true) && envBool("AI_LOG_ENABLED", true); -} - -function aiRunnerColorsEnabled(): boolean { - return envBool("AI_RUNNER_LOG_COLORS", true) && !process.env.NO_COLOR; -} - -function configuredMinLevel(): AiRunnerLogLevel { - const raw = process.env.AI_LOG_LEVEL?.trim().toLowerCase(); - if (raw && raw in LOG_LEVEL_WEIGHT) return raw as AiRunnerLogLevel; - return "debug"; -} - -function shouldWriteLevel(level: AiRunnerLogLevel): boolean { - return LOG_LEVEL_WEIGHT[level] >= LOG_LEVEL_WEIGHT[configuredMinLevel()]; -} - -function paintAiLog(value: string, color: keyof typeof AI_RUNNER_LOG_COLORS): string { - if (!aiRunnerColorsEnabled()) return value; - return `${AI_RUNNER_LOG_COLORS[color]}${value}${AI_RUNNER_LOG_COLORS.reset}`; -} - -function truncateAiLogString(value: string, max = AI_RUNNER_LOG_MAX_STRING): string { - if (value.length <= max) return value; - return `${value.slice(0, max)}… (+${value.length - max} chars)`; -} - -function safeJsonParseObject(value?: string): Record { - if (!value?.trim()) return {}; - - try { - const parsed: unknown = JSON.parse(value); - return parsed && typeof parsed === "object" && !Array.isArray(parsed) - ? parsed as Record - : {}; - } catch { - return {}; - } -} - -function isSecretKey(keyPath: string): boolean { - const normalized = keyPath.toLowerCase(); - return normalized.includes("token") - || normalized.includes("secret") - || normalized.includes("apikey") - || normalized.includes("api_key") - || normalized.includes("authorization") - || normalized.endsWith(".key") - || normalized === "key"; -} - -function isPromptKey(keyPath: string): boolean { - const normalized = keyPath.toLowerCase(); - return normalized.includes("prompt") || normalized.includes("systemprompt"); -} - -function isTextPreviewKey(keyPath: string): boolean { - const normalized = keyPath.toLowerCase(); - return normalized.includes("content") - || normalized.includes("message") - || normalized.includes("text") - || normalized.includes("preview") - || normalized.includes("input") - || normalized.includes("output"); -} - -function isToolArgsKey(keyPath: string): boolean { - const normalized = keyPath.toLowerCase(); - return normalized.endsWith("args") - || normalized.endsWith("arguments") - || normalized.includes("toolargs") - || normalized.includes("tool_args"); -} - -function isDaoKey(keyPath: string): boolean { - const normalized = keyPath.toLowerCase(); - return normalized.includes("dao") - || normalized.includes("database") - || normalized.includes("db.") - || normalized.includes("sql") - || normalized.includes("chunk"); -} - -function shouldRedactKey(keyPath: string): boolean { - if (isSecretKey(keyPath)) return true; - if (isPromptKey(keyPath) && !envBool("AI_LOG_PROMPTS", false)) return true; - if (isToolArgsKey(keyPath) && !envBool("AI_LOG_TOOL_ARGS", false)) return true; - if (isDaoKey(keyPath) && !envBool("AI_LOG_DAO", false)) return true; - if (isTextPreviewKey(keyPath) && !envBool("AI_LOG_TEXT_PREVIEW", false)) return true; - return false; -} - -function primitiveToLogValue(value: unknown): unknown { - if (value instanceof Error) { - return { - name: value.name, - message: value.message, - stack: value.stack?.split("\n").slice(0, 6).join("\n"), - }; - } - - if (typeof value === "string") return truncateAiLogString(value); - if (typeof value === "number" || typeof value === "boolean" || value === null || value === undefined) return value; - if (typeof value === "bigint") return value.toString(); - if (typeof value === "function") return `[Function ${value.name || "anonymous"}]`; - if (Buffer.isBuffer(value)) return ``; - return undefined; -} - -export function flattenAiLogDetails( - value: unknown, - keyPath = "", - depth = 0, - seen = new WeakSet(), -): Record { - if (keyPath && shouldRedactKey(keyPath)) { - return {[keyPath]: ""}; - } - - const primitive = primitiveToLogValue(value); - if (primitive !== undefined || value === undefined) { - return keyPath ? {[keyPath]: primitive} : {value: primitive}; - } - - if (typeof value !== "object" || value === null) { - return keyPath ? {[keyPath]: String(value)} : {value: String(value)}; - } - - if (seen.has(value)) { - return keyPath ? {[keyPath]: "[Circular]"} : {value: "[Circular]"}; - } - seen.add(value); - - if (Array.isArray(value)) { - if (depth >= 2) { - return keyPath ? {[keyPath]: `[Array ${value.length}]`} : {value: `[Array ${value.length}]`}; - } - - const entries: Record = {}; - value.slice(0, AI_RUNNER_LOG_MAX_ARRAY).forEach((item, index) => { - Object.assign(entries, flattenAiLogDetails(item, keyPath ? `${keyPath}.${index}` : String(index), depth + 1, seen)); - }); - if (value.length > AI_RUNNER_LOG_MAX_ARRAY) { - entries[keyPath ? `${keyPath}.__more` : "__more"] = value.length - AI_RUNNER_LOG_MAX_ARRAY; - } - return entries; - } - - if (depth >= 3) { - return keyPath ? {[keyPath]: "[Object]"} : {value: "[Object]"}; - } - - const entries: Record = {}; - for (const [key, raw] of Object.entries(value as Record)) { - const childPath = keyPath ? `${keyPath}.${key}` : key; - - if ((key.toLowerCase() === "data" || key.toLowerCase() === "image_url" || key.toLowerCase().endsWith("b64")) && typeof raw === "string") { - entries[childPath] = `<${raw.length} chars>`; - continue; - } - - Object.assign(entries, flattenAiLogDetails(raw, childPath, depth + 1, seen)); - } - - return entries; -} - -export function redactLogValue(value: unknown): Record { - return flattenAiLogDetails(value); -} - -function formatAiLogDetails(details?: AiRunnerLogDetails): string { - if (!details || !Object.keys(details).length) return ""; - - const flattened = flattenAiLogDetails(details); - const chunks = Object.entries(flattened).map(([key, value]) => { - const safeValue = typeof value === "string" ? value : JSON.stringify(value); - return `${paintAiLog(key, "key")}=${paintAiLog(safeValue ?? "undefined", "value")}`; - }); - - return ` ${chunks.join(" ")}`; -} - -export function aiLog(level: AiRunnerLogLevel, event: string, details?: AiRunnerLogDetails): void { - if (!aiRunnerLogsEnabled() || !shouldWriteLevel(level)) return; - - const timestamp = paintAiLog(new Date().toISOString(), "dim"); - const prefix = paintAiLog(AI_RUNNER_LOG_PREFIX, "bold"); - const levelText = paintAiLog(level.toUpperCase().padEnd(7), level); - const eventText = paintAiLog(event, "label"); - const line = `${timestamp} ${prefix} ${levelText} ${eventText}${formatAiLogDetails(details)}`; - - if (level === "error") { - console.error(line); - } else if (level === "warn") { - console.warn(line); - } else { - console.log(line); - } -} - -export function aiLogDuration(startedAt: number): string { - const ms = Date.now() - startedAt; - if (ms < 1000) return `${ms}ms`; - return `${(ms / 1000).toFixed(2)}s`; -} - -export function aiLogToolCall(toolCall: AiLogToolCallLike): Record { - return { - id: toolCall.id, - name: toolCall.name, - arguments: safeJsonParseObject(toolCall.argumentsText), - }; -} - -export function aiLogMessageIdentity(msg: Message | undefined): Record | undefined { - if (!msg) return undefined; - return { - chatId: msg.chat?.id, - chatType: msg.chat?.type, - messageId: msg.message_id, - fromId: msg.from?.id, - username: msg.from?.username, - }; -} - -export function aiLogProviderTarget(target: {provider: string; purpose?: string; model?: string; baseUrl?: string; apiKey?: string} | undefined): Record | undefined { - if (!target) return undefined; - return { - provider: target.provider, - purpose: target.purpose, - model: target.model, - baseUrl: target.baseUrl, - apiKey: target.apiKey, - }; -} +export * from "../logging/ai-logger"; diff --git a/src/ai/provider-request-queue.ts b/src/ai/provider-request-queue.ts index c8f4ea5..08e2e7a 100644 --- a/src/ai/provider-request-queue.ts +++ b/src/ai/provider-request-queue.ts @@ -1,5 +1,8 @@ import {Environment} from "../common/environment"; import {AiProvider} from "../model/ai-provider"; +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("ai-provider-queue"); export type AiRequestQueueTarget = { provider: AiProvider; @@ -31,6 +34,7 @@ class AiProviderRequestQueue { enqueue(target: AiRequestQueueTarget, options: EnqueueOptions): Promise { if (options.signal?.aborted) { + logger.debug("enqueue.rejected.aborted", {provider: target.provider, model: target.model, baseUrl: target.baseUrl}); return Promise.reject(new Error("Aborted")); } @@ -53,12 +57,14 @@ class AiProviderRequestQueue { const removed = this.removeWaitingEntry(entry); if (!removed) return; + logger.debug("entry.cancelled", {provider: target.provider, model: target.model, baseUrl: target.baseUrl, queueKey}); reject(new Error("Aborted")); this.schedule(target); }; options.signal?.addEventListener("abort", entry.abortHandler, {once: true}); this.getOrCreateQueue(queueKey).push(entry); + logger.debug("enqueue.accepted", {provider: target.provider, model: target.model, baseUrl: target.baseUrl, queued: this.getOrCreateQueue(queueKey).length, active: this.activeCount(queueKey)}); this.schedule(target); }); } @@ -132,12 +138,14 @@ class AiProviderRequestQueue { } if (entry.signal?.aborted) { + logger.debug("entry.skipped.aborted", {provider: target.provider, model: target.model, baseUrl: target.baseUrl, queueKey}); entry.reject(new Error("Aborted")); continue; } entry.started = true; this.setActiveCount(queueKey, this.activeCount(queueKey) + 1); + logger.debug("entry.started", {provider: target.provider, model: target.model, baseUrl: target.baseUrl, queued: queue.length, active: this.activeCount(queueKey)}); void this.runEntry(entry); } @@ -150,7 +158,9 @@ class AiProviderRequestQueue { private async runEntry(entry: QueueEntry): Promise { try { entry.resolve(await entry.run()); + logger.debug("entry.done", {provider: entry.target.provider, model: entry.target.model, baseUrl: entry.target.baseUrl}); } catch (e) { + logger.error("entry.failed", {provider: entry.target.provider, model: entry.target.model, baseUrl: entry.target.baseUrl, error: e}); entry.reject(e); } finally { this.setActiveCount(entry.queueKey, this.activeCount(entry.queueKey) - 1); @@ -168,10 +178,10 @@ class AiProviderRequestQueue { })).then(results => { for (const result of results) { if (result.status === "rejected") { - console.error(result.reason); + logger.error("position_update.failed", {provider: target.provider, model: target.model, reason: result.reason}); } } - }).catch(console.error); + }).catch(error => logger.error("position_updates.failed", {provider: target.provider, model: target.model, error})); } private deleteQueueIfIdle(queueKey: string, queue: QueueEntry[]): void { diff --git a/src/ai/telegram-attachments.ts b/src/ai/telegram-attachments.ts index d00e810..90dd011 100644 --- a/src/ai/telegram-attachments.ts +++ b/src/ai/telegram-attachments.ts @@ -8,6 +8,7 @@ import {StoredAttachment, StoredAttachmentKind} from "../model/stored-attachment import {performFFmpeg} from "../util/ffmpeg"; import ffmpeg from "fluent-ffmpeg"; import {AsyncSemaphore, KeyedAsyncLock} from "../util/async-lock"; +import {appLogger} from "../logging/logger"; export type AiDownloadedFile = { kind: StoredAttachmentKind; @@ -20,6 +21,7 @@ export type AiDownloadedFile = { const cachePathLocks = new KeyedAsyncLock(); const ffmpegSemaphore = new AsyncSemaphore(2); +const logger = appLogger.child("attachments"); function safeFileName(value: string): string { return value.replace(/[\\/:*?"<>|\u0000-\u001F]/g, "_").slice(0, 180); @@ -90,31 +92,48 @@ function cachePathFor(kind: StoredAttachmentKind, fileUniqueId: string | undefin } async function downloadToCache(kind: StoredAttachmentKind, fileId: string, fileName: string, mimeType?: string, fileUniqueId?: string): Promise { + const startedAt = Date.now(); + logger.debug("download.start", {kind, fileId, fileName, mimeType}); const file = await bot.getFile({file_id: fileId}); const finalFileName = fileNameWithExtension(fileName, mimeType, file.file_path); const location = cachePathFor(kind, fileUniqueId, fileId, finalFileName); await cachePathLocks.runExclusive(location, async () => { - if (fs.existsSync(location)) return; + if (fs.existsSync(location)) { + logger.trace("download.cache_hit", {kind, location}); + return; + } const buffer = await downloadTelegramFile(file.file_path); - if (!buffer) return; + if (!buffer) { + logger.warn("download.empty", {kind, fileId, telegramFilePath: file.file_path}); + return; + } const tempLocation = `${location}.${process.pid}.${Date.now()}.tmp`; fs.mkdirSync(path.dirname(location), {recursive: true}); fs.writeFileSync(tempLocation, buffer); fs.renameSync(tempLocation, location); + logger.debug("download.saved", {kind, location, bytes: buffer.length, duration: logger.duration(startedAt)}); }); return {kind, fileId, fileUniqueId, fileName: finalFileName, mimeType, cachePath: location}; } async function convertAudioToWav(input: string, output: string, noVideo = false): Promise { + const startedAt = Date.now(); + logger.debug("audio.convert.start", {input, output, noVideo}); await cachePathLocks.runExclusive(output, async () => { - if (fs.existsSync(output)) return; + if (fs.existsSync(output)) { + logger.trace("audio.convert.cache_hit", {output}); + return; + } await ffmpegSemaphore.runExclusive(async () => { - if (fs.existsSync(output)) return; + if (fs.existsSync(output)) { + logger.trace("audio.convert.cache_hit", {output}); + return; + } const tempOutput = `${output}.${process.pid}.${Date.now()}.tmp.wav`; try { @@ -125,14 +144,16 @@ async function convertAudioToWav(input: string, output: string, noVideo = false) .toFormat("wav") .save(tempOutput) .on("progress", (progress) => { - console.log("progress", progress); + logger.trace("audio.convert.progress", {input, output, progress}); }); }); fs.renameSync(tempOutput, output); + logger.debug("audio.convert.done", {input, output, duration: logger.duration(startedAt)}); } catch (e) { if (fs.existsSync(tempOutput)) { fs.rmSync(tempOutput, {force: true}); } + logger.error("audio.convert.failed", {input, output, error: e}); throw e; } }); @@ -140,7 +161,9 @@ async function convertAudioToWav(input: string, output: string, noVideo = false) } export async function cacheMessageAttachments(msg: Message): Promise { + const startedAt = Date.now(); const result: StoredAttachment[] = []; + logger.debug("message.cache.start", {chatId: msg.chat?.id, messageId: msg.message_id}); try { if (msg.photo?.length) { @@ -202,10 +225,12 @@ export async function cacheMessageAttachments(msg: Message): Promise fs.existsSync(attachment.cachePath)) .map(attachment => ({ @@ -219,6 +244,7 @@ export function attachmentsToDownloadedFiles(attachments: StoredAttachment[]): A } export function cleanupDownloads(files: AiDownloadedFile[]): void { + logger.trace("downloaded_files.cleanup", {files: files.length}); // Files stay on disk in the message cache; drop in-memory buffers eagerly. for (const file of files) { file.buffer = Buffer.alloc(0); diff --git a/src/ai/tools/brave-search.ts b/src/ai/tools/brave-search.ts index 3d64929..74f7468 100644 --- a/src/ai/tools/brave-search.ts +++ b/src/ai/tools/brave-search.ts @@ -1,4 +1,7 @@ import axios from "axios"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("brave-search"); import {Environment} from "../../common/environment"; import {logError} from "../../util/utils"; import {AiTool} from "../tool-types"; @@ -264,7 +267,8 @@ function normalizeBraveResultFilter(value: unknown): string { } export async function webSearch(args?: Record) { - console.log("braveSearch()"); + const startedAt = Date.now(); + logger.info("start", {args}); try { const query = asNonEmptyString(args?.query); @@ -370,7 +374,7 @@ export async function webSearch(args?: Record) { response: data ?? null, }; } finally { - console.log("END: braveSearch()"); + logger.debug("done", {duration: logger.duration(startedAt)}); } } diff --git a/src/ai/tools/create-note.ts b/src/ai/tools/create-note.ts index 3dca0d7..8ed5d1f 100644 --- a/src/ai/tools/create-note.ts +++ b/src/ai/tools/create-note.ts @@ -4,6 +4,9 @@ import {readFile, writeFile} from "node:fs/promises"; import {NOTES_HEADER, notesDir, notesRootFile} from "../../index"; import {asNonEmptyString} from "./utils"; import fs from "node:fs"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("create-note"); export type CreateNoteResult = | { success: true; filePath: string } @@ -38,7 +41,8 @@ export const createNoteTool = { export async function createNote( args?: Record ): Promise { - console.log("CREATE_NOTE; ARGS: ", args); + const startedAt = Date.now(); + logger.debug("start", {args}); const fileName = asNonEmptyString(args?.fileName) ?? ""; if (!fileName.trim().length) { @@ -76,8 +80,10 @@ export async function createNote( } await writeFile(notesRootFile, rootContent, "utf-8"); + logger.debug("done", {fileName, filePath: newFilePath, duration: logger.duration(startedAt)}); return {success: true, filePath: newFilePath}; } catch (error) { + logger.error("failed", {duration: logger.duration(startedAt), error}); const errorMessage = error instanceof Error ? error.message : String(error); return {success: false, error: `Failed to process files: ${errorMessage}`}; } diff --git a/src/ai/tools/list-notes.ts b/src/ai/tools/list-notes.ts index bd17ca5..138bd7c 100644 --- a/src/ai/tools/list-notes.ts +++ b/src/ai/tools/list-notes.ts @@ -3,6 +3,9 @@ import path from "node:path"; import {readdir, readFile, unlink, writeFile} from "node:fs/promises"; import {notesDir, notesRootFile} from "../../index"; import {asNonEmptyString} from "./utils"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("notes"); export type NoteListItem = { fileName: string; @@ -58,7 +61,8 @@ export const getNoteContentTool = { } satisfies AiTool; export async function listNotes(): Promise { - console.log("LIST_NOTES"); + const startedAt = Date.now(); + logger.debug("list.start"); try { const entries = await readdir(notesDir, {withFileTypes: true}); @@ -91,8 +95,10 @@ export async function listNotes(): Promise { notes.sort((a, b) => a.title.localeCompare(b.title)); + logger.debug("list.done", {notes: notes.length, duration: logger.duration(startedAt)}); return {success: true, notes}; } catch (error) { + logger.error("list.failed", {duration: logger.duration(startedAt), error}); const errorMessage = error instanceof Error ? error.message : String(error); return {success: false, error: `Failed to list notes: ${errorMessage}`}; } @@ -101,7 +107,8 @@ export async function listNotes(): Promise { export async function getNoteContent( args?: Record, ): Promise { - console.log("GET_NOTE_CONTENT; ARGS: ", args); + const startedAt = Date.now(); + logger.debug("get_content.start", {args}); const fileName = asNonEmptyString(args?.fileName) ?? ""; if (!fileName.trim().length) { @@ -118,6 +125,7 @@ export async function getNoteContent( const normalizedFileName = path.basename(noteFilePath); const relativePath = path.relative(path.dirname(notesRootFile), noteFilePath); + logger.debug("get_content.done", {fileName: normalizedFileName, relativePath, chars: content.length, duration: logger.duration(startedAt)}); return { success: true, fileName: normalizedFileName, @@ -127,6 +135,7 @@ export async function getNoteContent( content, }; } catch (error) { + logger.error("list.failed", {duration: logger.duration(startedAt), error}); const errorMessage = error instanceof Error ? error.message : String(error); return {success: false, error: `Failed to read note: ${errorMessage}`}; } @@ -219,7 +228,8 @@ export const deleteNoteTool = { export async function updateNoteContent( args?: Record, ): Promise { - console.log("UPDATE_NOTE_CONTENT; ARGS: ", args); + const startedAt = Date.now(); + logger.debug("update_content.start", {args}); const fileName = asNonEmptyString(args?.fileName) ?? ""; if (!fileName.trim().length) { @@ -239,9 +249,11 @@ export async function updateNoteContent( try { await readFile(noteFilePath, "utf-8"); await writeFile(noteFilePath, content, "utf-8"); + logger.debug("update_content.done", {fileName, filePath: noteFilePath, chars: content.length, duration: logger.duration(startedAt)}); return {success: true, filePath: noteFilePath}; } catch (error) { + logger.error("list.failed", {duration: logger.duration(startedAt), error}); const errorMessage = error instanceof Error ? error.message : String(error); return {success: false, error: `Failed to update note: ${errorMessage}`}; } @@ -250,7 +262,8 @@ export async function updateNoteContent( export async function deleteNote( args?: Record, ): Promise { - console.log("DELETE_NOTE; ARGS: ", args); + const startedAt = Date.now(); + logger.debug("delete.start", {args}); const fileName = asNonEmptyString(args?.fileName) ?? ""; if (!fileName.trim().length) { @@ -265,9 +278,11 @@ export async function deleteNote( try { await unlink(noteFilePath); await removeNoteLinkFromRoot(noteFilePath); + logger.debug("delete.done", {fileName, filePath: noteFilePath, duration: logger.duration(startedAt)}); return {success: true, filePath: noteFilePath}; } catch (error) { + logger.error("list.failed", {duration: logger.duration(startedAt), error}); const errorMessage = error instanceof Error ? error.message : String(error); return {success: false, error: `Failed to delete note: ${errorMessage}`}; } diff --git a/src/ai/tools/market-rates.ts b/src/ai/tools/market-rates.ts index 109f6b9..e5bc317 100644 --- a/src/ai/tools/market-rates.ts +++ b/src/ai/tools/market-rates.ts @@ -1,5 +1,8 @@ import {AiTool} from "../tool-types"; import axios from "axios"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("market-rates"); export const getMarketRatesTool = { type: "function", @@ -59,11 +62,14 @@ export const marketRatesToolPrompt = [ ].join("\n"); export async function getMarketRates(): Promise { + const startedAt = Date.now(); try { + logger.info("start"); const response = await axios.get("https://apid.r00t.top/api/v2/currency/rates"); + logger.debug("done", {duration: logger.duration(startedAt), status: response.status}); return response.data; } catch (e: unknown) { - console.error("GET_MARKET_RATES", e); + logger.error("failed", {duration: logger.duration(startedAt), error: e}); return undefined; } } \ No newline at end of file diff --git a/src/ai/tools/python-interpretator.ts b/src/ai/tools/python-interpretator.ts index 3f827af..f724dbb 100644 --- a/src/ai/tools/python-interpretator.ts +++ b/src/ai/tools/python-interpretator.ts @@ -5,6 +5,9 @@ import path from "node:path"; import {AiTool} from "../tool-types"; import {Environment} from "../../common/environment"; import {randomUUID} from "node:crypto"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("python-interpreter"); export const PYTHON_INTERPRETER_TOOL_NAME = "python_interpreter"; @@ -203,17 +206,17 @@ export async function runPythonInterpreter( }; } - console.time("python.syntax"); + const syntaxStartedAt = Date.now(); const syntax = await validatePythonSyntax(args.code, options); - console.timeEnd("python.syntax"); + logger.debug("syntax.done", {duration: logger.duration(syntaxStartedAt), ok: syntax.ok}); if (!syntax.ok) { return syntax; } - console.time("python.execution"); + const executionStartedAt = Date.now(); const result = await executePythonCode(args, options); - console.timeEnd("python.execution"); + logger.debug("execution.done", {duration: logger.duration(executionStartedAt), ok: result.ok, phase: result.phase}); return result; } @@ -293,7 +296,8 @@ async function executePythonCode( args: PythonInterpreterArgs, options: PythonInterpreterOptions = {}, ): Promise { - console.log("EXECUTE_PYTHON_CODE", "ARGS: ", JSON.stringify(args), "; OPTIONS: ", JSON.stringify(options)); + const startedAt = Date.now(); + logger.info("execute.start", {args, options}); const pythonBinary = options.pythonBinary ?? process.env.PYTHON_INTERPRETER_BINARY ?? "C:\\Users\\meloda\\Desktop\\AI_BOT\\.venv\\Scripts\\python.exe"; @@ -329,7 +333,7 @@ async function executePythonCode( mode: 0o600, }); - console.log("EXECUTE_PYTHON_CODE", "SCRIPT FILE WRITTEN", new Date()); + logger.debug("script.written", {tempDir, userScriptPath, runnerPath, duration: logger.duration(startedAt)}); const result = await runProcess({ command: pythonBinary, @@ -346,10 +350,10 @@ async function executePythonCode( }, }); - console.log("EXECUTE_PYTHON_CODE", "RESULT ACHIEVED", new Date()); + logger.debug("process.done", {duration: logger.duration(startedAt), exitCode: result.exitCode, timedOut: result.timedOut, outputTruncated: result.outputTruncated}); if (result.timedOut) { - console.log("EXECUTE_PYTHON_CODE", "RESULT ERROR TIMED OUT", new Date()); + logger.warn("process.timeout", {duration: logger.duration(startedAt)}); return { ok: false, phase: "execution", @@ -365,7 +369,7 @@ async function executePythonCode( } if (result.outputTruncated) { - console.log("EXECUTE_PYTHON_CODE", "RESULT ERROR TRUNCATED", new Date()); + logger.warn("process.output_truncated", {duration: logger.duration(startedAt), stdoutChars: result.stdout.length, stderrChars: result.stderr.length}); return { ok: false, @@ -382,7 +386,7 @@ async function executePythonCode( } if (result.exitCode !== 0) { - console.log("EXECUTE_PYTHON_CODE", "RESULT ERROR EXIT CODE", new Date(), "\n", JSON.stringify(result, null, 2)); + logger.warn("process.non_zero_exit", {duration: logger.duration(startedAt), result}); return { ok: false, @@ -398,7 +402,7 @@ async function executePythonCode( }; } - console.log("EXECUTE_PYTHON_CODE", "RESULT NORMAL", new Date()); + logger.debug("process.ok", {duration: logger.duration(startedAt)}); const { artifacts, @@ -420,7 +424,7 @@ async function executePythonCode( skippedArtifacts, }; } catch (error) { - console.log("EXECUTE_PYTHON_CODE", "RESULT ERROR", new Date()); + logger.error("execute.failed", {duration: logger.duration(startedAt), error}); return { ok: false, phase: "internal", diff --git a/src/ai/tools/runtime.ts b/src/ai/tools/runtime.ts index c5be0b4..4403251 100644 --- a/src/ai/tools/runtime.ts +++ b/src/ai/tools/runtime.ts @@ -1,6 +1,9 @@ import {getToolHandlers} from "./registry"; import {normalizeToolArguments} from "./utils"; import {PYTHON_INTERPRETER_TOOL_NAME, PythonInterpreterInputFile, runPythonInterpreter} from "./python-interpretator"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("runtime"); export type ToolRuntimeContext = { pythonInputFiles?: PythonInterpreterInputFile[]; @@ -16,7 +19,9 @@ export async function executeToolCall( args?: unknown, context: ToolRuntimeContext = {}, ): Promise { + const startedAt = Date.now(); const handler = getToolHandlers()[name]; + logger.info("execute.start", {name, args}); if (!handler) { return stringifyToolResult({ @@ -35,14 +40,17 @@ export async function executeToolCall( }); const s = stringifyToolResult(result); - console.log("PYTHON_INTERPRETER_STRING_RESULT", s); + logger.debug("execute.done", {name, chars: s.length, duration: logger.duration(startedAt)}); return s; } const result = await handler(normalizeToolArguments(args)); - return stringifyToolResult(result); + const s = stringifyToolResult(result); + logger.debug("execute.done", {name, chars: s.length, duration: logger.duration(startedAt)}); + return s; } catch (error) { + logger.error("execute.failed", {name, duration: logger.duration(startedAt), error}); return stringifyToolResult({ error: error instanceof Error ? error.message : String(error), }); diff --git a/src/ai/tools/search-notes.ts b/src/ai/tools/search-notes.ts index 957039d..e042437 100644 --- a/src/ai/tools/search-notes.ts +++ b/src/ai/tools/search-notes.ts @@ -3,6 +3,9 @@ import path from "node:path"; import {readdir, readFile} from "node:fs/promises"; import {notesDir, notesRootFile} from "../../index"; import {asNonEmptyString} from "./utils"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("search-notes"); export type SearchNoteMatchedField = "file_name" | "title" | "content"; @@ -51,7 +54,8 @@ export const searchNotesTool = { export async function searchNotes( args?: Record, ): Promise { - console.log("SEARCH_NOTES; ARGS: ", args); + const startedAt = Date.now(); + logger.debug("start", {args}); const query = asNonEmptyString(args?.query) ?? ""; if (!query.trim().length) { @@ -127,6 +131,7 @@ export async function searchNotes( .sort((a, b) => b.score - a.score) .slice(0, limit); + logger.debug("done", {query, limit, results: results.length, duration: logger.duration(startedAt)}); return {success: true, results}; } catch (error) { const errorMessage = error instanceof Error ? error.message : String(error); diff --git a/src/ai/tools/send-note-file.ts b/src/ai/tools/send-note-file.ts index 1f2bb06..678c1d8 100644 --- a/src/ai/tools/send-note-file.ts +++ b/src/ai/tools/send-note-file.ts @@ -5,6 +5,9 @@ import {notesRootFile} from "../../index"; import {asNonEmptyString} from "./utils"; import {buildSafeNoteFilePath} from "./list-notes"; import z from "zod"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("get-note-file"); export type NoteFileAttachment = { type: "local_file"; @@ -64,7 +67,7 @@ export const getNoteFileTool = { export async function getNoteFile( args?: Record, ): Promise { - console.log("GET_NOTE_FILE; ARGS: ", args); + logger.debug("start", {args}); const fileName = asNonEmptyString(args?.fileName) ?? ""; if (!fileName.trim().length) { @@ -100,7 +103,7 @@ export async function getNoteFile( }, }; - console.log("GET_NOTE_FILE; RESULT: ", result); + logger.debug("done", {fileName: result.attachment.fileName, relativePath: result.attachment.relativePath, sizeBytes: result.attachment.sizeBytes}); return result; } catch (error) { diff --git a/src/ai/tools/utils.ts b/src/ai/tools/utils.ts index d9a7ed1..6dfba61 100644 --- a/src/ai/tools/utils.ts +++ b/src/ai/tools/utils.ts @@ -1,5 +1,8 @@ import {Ollama} from "ollama"; import {z} from "zod"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("utils"); export function asNonEmptyString(value: unknown): string | undefined { return typeof value === "string" && value.trim().length > 0 @@ -79,14 +82,15 @@ export async function unloadAllOllamaModels(ollama: Ollama, exceptFor?: string[] ); await Promise.all(unloadPromises); - console.log("All models have been requested to unload" + (exceptFor?.length ? ` except for [${exceptFor?.join(", ")}].` : ".")); + logger.info("ollama.unload_all.done", {count: modelsToUnload.length, exceptFor}); } catch (error) { - console.error("Error unloading models:", error); + logger.error("ollama.unload_all.failed", {exceptFor, error}); } } export async function loadOllamaModel(model: string, ollama: Ollama, contextLength: number): Promise { try { + logger.info("ollama.load.start", {model, contextLength}); await ollama.generate({ model: model, stream: false, @@ -95,9 +99,10 @@ export async function loadOllamaModel(model: string, ollama: Ollama, contextLeng num_ctx: contextLength } }); + logger.info("ollama.load.done", {model, contextLength}); return true; } catch (e: unknown) { - console.error("Error loading Ollama model:", model); + logger.error("ollama.load.failed", {model, contextLength, error: e}); return false; } } diff --git a/src/ai/tools/weather.ts b/src/ai/tools/weather.ts index 290f7a9..4201a96 100644 --- a/src/ai/tools/weather.ts +++ b/src/ai/tools/weather.ts @@ -1,4 +1,7 @@ import axios from "axios"; +import {toolsLogger} from "./tool-logger"; + +const logger = toolsLogger.child("weather"); import {Environment} from "../../common/environment"; import {logError} from "../../util/utils"; import {AiTool} from "../tool-types"; @@ -43,7 +46,8 @@ export const weatherToolPrompt = [ ].join("\n"); export async function getWeather(args?: Record): Promise | null> { - console.log("getWeather()"); + const startedAt = Date.now(); + logger.info("start", {args}); try { const city = asNonEmptyString(args?.city); const lang = asNonEmptyString(args?.lang); @@ -61,7 +65,7 @@ export async function getWeather(args?: Record): Promise): Promise): Promise; diff --git a/src/ai/unified-ai-runner.shared.ts b/src/ai/unified-ai-runner.shared.ts index 22995e4..10fb31c 100644 --- a/src/ai/unified-ai-runner.shared.ts +++ b/src/ai/unified-ai-runner.shared.ts @@ -35,7 +35,7 @@ import {OllamaChatMessage} from "./ollama-chat-message"; import {GeminiMessage} from "./gemini-chat-message"; import {prepareTelegramMarkdownV2} from "../util/markdown-v2-renderer"; import {AiRuntimeTarget, createMistralClient, getGeminiApiMode, resolveAiRuntimeTarget} from "./ai-runtime-target"; -import {aiLog, aiLogDuration, aiLogProviderTarget, aiLogToolCall} from "./ai-logger"; +import {aiLog, aiLogDuration, aiLogProviderTarget, aiLogToolCall} from "../logging/ai-logger"; export type {Message} from "typescript-telegram-bot-api"; export type {AiRuntimeTarget} from "./ai-runtime-target"; @@ -443,7 +443,6 @@ export function resolveAiRequestQueueTarget( export function roundStatus(round: number, firstRoundStatus: string, content?: string, toolCalls?: ToolCallData[], thinking?: boolean): string | null { if (content?.length && !toolCalls?.length && !thinking) { - // console.log("ROUND_STATUS", "null"); return null; } @@ -452,7 +451,6 @@ export function roundStatus(round: number, firstRoundStatus: string, content?: s : round === 0 ? firstRoundStatus : Environment.waitThinkText; - // console.log("ROUND_STATUS", status); return status; } @@ -1085,11 +1083,11 @@ export function appendTranscriptToChatMessages( return partType === "input_text" || partType === "input_image"; }); - lastUser.content.push( - (usesOpenAiResponsesParts - ? {type: "input_text", text} - : {type: "text", text}) as any, - ); + if (usesOpenAiResponsesParts) { + (lastUser.content as ResponseInputMessageContentList).push({type: "input_text", text}); + } else { + (lastUser.content as OpenAiCompatibleContentPart[]).push({type: "text", text}); + } } } diff --git a/src/ai/unified-ai-runner.tool-ranker.ts b/src/ai/unified-ai-runner.tool-ranker.ts index 218a770..482506b 100644 --- a/src/ai/unified-ai-runner.tool-ranker.ts +++ b/src/ai/unified-ai-runner.tool-ranker.ts @@ -1,6 +1,6 @@ import {Tool} from "ollama"; import {AiRuntimeTarget, createOllamaClient} from "./ai-runtime-target"; -import {aiLog, aiLogDuration, aiLogProviderTarget} from "./ai-logger"; +import {aiLog, aiLogDuration, aiLogProviderTarget} from "../logging/ai-logger"; import {allToolSchemaNames, isRecord, JsonObject, RuntimeConfigSnapshot, safeJsonParseObject, toolSchemaNames} from "./unified-ai-runner.shared"; type RankedToolStep = { diff --git a/src/ai/unified-ai-runner.ts b/src/ai/unified-ai-runner.ts index 37b247f..80a8aea 100644 --- a/src/ai/unified-ai-runner.ts +++ b/src/ai/unified-ai-runner.ts @@ -16,7 +16,7 @@ import {OllamaChatMessage} from "./ollama-chat-message"; import {GeminiMessage} from "./gemini-chat-message"; import {buildAiRegenerateCallbackData} from "./regenerate-callback"; import {createOllamaClient, getGeminiApiMode} from "./ai-runtime-target"; -import {aiLog, aiLogDuration, aiLogMessageIdentity, aiLogProviderTarget} from "./ai-logger"; +import {aiLog, aiLogDuration, aiLogMessageIdentity, aiLogProviderTarget} from "../logging/ai-logger"; import {runOpenAi, runOpenAiCompatibleChat} from "./unified-ai-runner.openai"; import {runOllama} from "./unified-ai-runner.ollama"; diff --git a/src/commands/choice.ts b/src/commands/choice.ts index cad8f5b..6feb606 100644 --- a/src/commands/choice.ts +++ b/src/commands/choice.ts @@ -3,6 +3,9 @@ import {Message} from "typescript-telegram-bot-api"; import {logError, oldReplyToMessage, randomValue} from "../util/utils"; import {prepareTelegramMarkdownV2} from "../util/markdown-v2-renderer"; import {Environment} from "../common/environment"; +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("command:choice"); export class Choice extends Command { command = "choice"; @@ -12,7 +15,7 @@ export class Choice extends Command { description = Environment.commandDescriptions.choice; async execute(msg: Message, match?: RegExpExecArray): Promise { - console.log("match", match); + logger.debug("execute", {chatId: msg.chat?.id, messageId: msg.message_id, match}); const payload = match?.[3] || ""; diff --git a/src/commands/gemini-get-model.ts b/src/commands/gemini-get-model.ts index b6c66b0..7da8652 100644 --- a/src/commands/gemini-get-model.ts +++ b/src/commands/gemini-get-model.ts @@ -1,15 +1,13 @@ -import {Command} from "../base/command"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderGetModelCommand} from "./provider-model-command"; -export class GeminiGetModel extends Command { - title = Environment.commandTitles.geminiGetModel; - description = Environment.commandDescriptions.geminiGetModel; - - async execute(msg: Message): Promise { - await replyToMessage({message: msg, text: await formatRuntimeModelInfo(AiProvider.GEMINI)}).catch(logError); +export class GeminiGetModel extends ProviderGetModelCommand { + constructor() { + super({ + provider: AiProvider.GEMINI, + title: Environment.commandTitles.geminiGetModel, + description: Environment.commandDescriptions.geminiGetModel, + }); } } diff --git a/src/commands/gemini-list-models.ts b/src/commands/gemini-list-models.ts index 7be16db..766f6bd 100644 --- a/src/commands/gemini-list-models.ts +++ b/src/commands/gemini-list-models.ts @@ -1,28 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {escapeHtml, logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {listProviderModels} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderListModelsCommand} from "./provider-model-command"; -export class GeminiListModels extends Command { - title = Environment.commandTitles.geminiListModels; - description = Environment.commandDescriptions.geminiListModels; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message): Promise { - try { - const models = (await listProviderModels(AiProvider.GEMINI)).sort((a, b) => a.localeCompare(b)); - const modelsString = escapeHtml(models.join("\n").substring(0, 4000)); - const text = Environment.modelListHeaderText + "
" + modelsString + "
"; - - await replyToMessage({message: msg, text, parse_mode: "HTML"}); - } catch (e) { - logError(e); - await replyToMessage({message: msg, text: Environment.modelListLoadFailedText}).catch(logError); - } +export class GeminiListModels extends ProviderListModelsCommand { + constructor() { + super({ + provider: AiProvider.GEMINI, + title: Environment.commandTitles.geminiListModels, + description: Environment.commandDescriptions.geminiListModels, + }); } } diff --git a/src/commands/gemini-set-model.ts b/src/commands/gemini-set-model.ts index 7242ad6..d1ac7f2 100644 --- a/src/commands/gemini-set-model.ts +++ b/src/commands/gemini-set-model.ts @@ -1,29 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {getRuntimeModel, setRuntimeModel, formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderSetModelCommand} from "./provider-model-command"; -export class GeminiSetModel extends Command { - argsMode = "required" as const; - - title = Environment.commandTitles.geminiSetModel; - description = Environment.commandDescriptions.geminiSetModel; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message, match?: RegExpExecArray | null): Promise { - const newModel = match?.[3]?.trim(); - if (newModel) setRuntimeModel(AiProvider.GEMINI, newModel); - - const model = getRuntimeModel(AiProvider.GEMINI); - const text = newModel - ? Environment.getSelectedModelWithInfoText(model, await formatRuntimeModelInfo(AiProvider.GEMINI)) - : Environment.getModelIsNotSetCurrentText(model); - - await replyToMessage({message: msg, text}).catch(logError); +export class GeminiSetModel extends ProviderSetModelCommand { + constructor() { + super({ + provider: AiProvider.GEMINI, + title: Environment.commandTitles.geminiSetModel, + description: Environment.commandDescriptions.geminiSetModel, + }); } } diff --git a/src/commands/mistral-get-model.ts b/src/commands/mistral-get-model.ts index 015bcb9..01b982a 100644 --- a/src/commands/mistral-get-model.ts +++ b/src/commands/mistral-get-model.ts @@ -1,15 +1,13 @@ -import {Command} from "../base/command"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderGetModelCommand} from "./provider-model-command"; -export class MistralGetModel extends Command { - title = Environment.commandTitles.mistralGetModel; - description = Environment.commandDescriptions.mistralGetModel; - - async execute(msg: Message): Promise { - await replyToMessage({message: msg, text: await formatRuntimeModelInfo(AiProvider.MISTRAL)}).catch(logError); +export class MistralGetModel extends ProviderGetModelCommand { + constructor() { + super({ + provider: AiProvider.MISTRAL, + title: Environment.commandTitles.mistralGetModel, + description: Environment.commandDescriptions.mistralGetModel, + }); } } diff --git a/src/commands/mistral-list-models.ts b/src/commands/mistral-list-models.ts index 6ff22e9..3b4a655 100644 --- a/src/commands/mistral-list-models.ts +++ b/src/commands/mistral-list-models.ts @@ -1,28 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {escapeHtml, logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {listProviderModels} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderListModelsCommand} from "./provider-model-command"; -export class MistralListModels extends Command { - title = Environment.commandTitles.mistralListModels; - description = Environment.commandDescriptions.mistralListModels; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message): Promise { - try { - const models = (await listProviderModels(AiProvider.MISTRAL)).sort((a, b) => a.localeCompare(b)); - const modelsString = escapeHtml(models.join("\n").substring(0, 4000)); - const text = Environment.modelListHeaderText + "
" + modelsString + "
"; - - await replyToMessage({message: msg, text, parse_mode: "HTML"}); - } catch (e) { - logError(e); - await replyToMessage({message: msg, text: Environment.modelListLoadFailedText}).catch(logError); - } +export class MistralListModels extends ProviderListModelsCommand { + constructor() { + super({ + provider: AiProvider.MISTRAL, + title: Environment.commandTitles.mistralListModels, + description: Environment.commandDescriptions.mistralListModels, + }); } } diff --git a/src/commands/mistral-set-model.ts b/src/commands/mistral-set-model.ts index 7c7551e..d7755a8 100644 --- a/src/commands/mistral-set-model.ts +++ b/src/commands/mistral-set-model.ts @@ -1,29 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {getRuntimeModel, setRuntimeModel, formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderSetModelCommand} from "./provider-model-command"; -export class MistralSetModel extends Command { - argsMode = "required" as const; - - title = Environment.commandTitles.mistralSetModel; - description = Environment.commandDescriptions.mistralSetModel; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message, match?: RegExpExecArray | null): Promise { - const newModel = match?.[3]?.trim(); - if (newModel) setRuntimeModel(AiProvider.MISTRAL, newModel); - - const model = getRuntimeModel(AiProvider.MISTRAL); - const text = newModel - ? Environment.getSelectedModelWithInfoText(model, await formatRuntimeModelInfo(AiProvider.MISTRAL)) - : Environment.getModelIsNotSetCurrentText(model); - - await replyToMessage({message: msg, text}).catch(logError); +export class MistralSetModel extends ProviderSetModelCommand { + constructor() { + super({ + provider: AiProvider.MISTRAL, + title: Environment.commandTitles.mistralSetModel, + description: Environment.commandDescriptions.mistralSetModel, + }); } } diff --git a/src/commands/ollama-get-model.ts b/src/commands/ollama-get-model.ts index bcf51a9..91490d8 100644 --- a/src/commands/ollama-get-model.ts +++ b/src/commands/ollama-get-model.ts @@ -1,15 +1,13 @@ -import {Command} from "../base/command"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderGetModelCommand} from "./provider-model-command"; -export class OllamaGetModel extends Command { - title = Environment.commandTitles.ollamaGetModel; - description = Environment.commandDescriptions.ollamaGetModel; - - async execute(msg: Message): Promise { - await replyToMessage({message: msg, text: await formatRuntimeModelInfo(AiProvider.OLLAMA)}).catch(logError); +export class OllamaGetModel extends ProviderGetModelCommand { + constructor() { + super({ + provider: AiProvider.OLLAMA, + title: Environment.commandTitles.ollamaGetModel, + description: Environment.commandDescriptions.ollamaGetModel, + }); } } diff --git a/src/commands/ollama-list-models.ts b/src/commands/ollama-list-models.ts index 8a5e1a0..ea6d3de 100644 --- a/src/commands/ollama-list-models.ts +++ b/src/commands/ollama-list-models.ts @@ -1,35 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; import {Environment} from "../common/environment"; -import {escapeHtml, logError, replyToMessage} from "../util/utils"; import {AiProvider} from "../model/ai-provider"; -import {listProviderModels} from "../ai/provider-model-runtime"; -import {createOllamaClient, resolveAiRuntimeTarget} from "../ai/ai-runtime-target"; +import {ProviderListModelsCommand} from "./provider-model-command"; -export class OllamaListModels extends Command { - title = Environment.commandTitles.ollamaListModels; - description = Environment.commandDescriptions.ollamaListModels; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message): Promise { - try { - const target = resolveAiRuntimeTarget(AiProvider.OLLAMA, "chat"); - const models = (await listProviderModels(AiProvider.OLLAMA)).sort((a, b) => a.localeCompare(b)); - const modelsString = escapeHtml(models.join("\n").substring(0, 4000)); - const loadedModels = ((await createOllamaClient(target).ps())?.models ?? []) - .map(model => model.model || model.name) - .filter((model): model is string => !!model); - const text = - Environment.getLoadedModelsText(loadedModels) + "\n\n" + - Environment.modelListHeaderText + "
" + modelsString + "
"; - - await replyToMessage({message: msg, text, parse_mode: "HTML"}); - } catch (e) { - logError(e); - await replyToMessage({message: msg, text: Environment.modelListLoadFailedText}).catch(logError); - } +export class OllamaListModels extends ProviderListModelsCommand { + constructor() { + super({ + provider: AiProvider.OLLAMA, + title: Environment.commandTitles.ollamaListModels, + description: Environment.commandDescriptions.ollamaListModels, + }); } } diff --git a/src/commands/ollama-set-model.ts b/src/commands/ollama-set-model.ts index 196868d..7050525 100644 --- a/src/commands/ollama-set-model.ts +++ b/src/commands/ollama-set-model.ts @@ -1,29 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {getRuntimeModel, setRuntimeModel, formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderSetModelCommand} from "./provider-model-command"; -export class OllamaSetModel extends Command { - argsMode = "required" as const; - - title = Environment.commandTitles.ollamaSetModel; - description = Environment.commandDescriptions.ollamaSetModel; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message, match?: RegExpExecArray | null): Promise { - const newModel = match?.[3]?.trim(); - if (newModel) setRuntimeModel(AiProvider.OLLAMA, newModel); - - const model = getRuntimeModel(AiProvider.OLLAMA); - const text = newModel - ? Environment.getSelectedModelWithInfoText(model, await formatRuntimeModelInfo(AiProvider.OLLAMA)) - : Environment.getModelIsNotSetCurrentText(model); - - await replyToMessage({message: msg, text}).catch(logError); +export class OllamaSetModel extends ProviderSetModelCommand { + constructor() { + super({ + provider: AiProvider.OLLAMA, + title: Environment.commandTitles.ollamaSetModel, + description: Environment.commandDescriptions.ollamaSetModel, + }); } } diff --git a/src/commands/openai-get-model.ts b/src/commands/openai-get-model.ts index 3a13875..a5b1b01 100644 --- a/src/commands/openai-get-model.ts +++ b/src/commands/openai-get-model.ts @@ -1,15 +1,13 @@ -import {Command} from "../base/command"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderGetModelCommand} from "./provider-model-command"; -export class OpenAIGetModel extends Command { - title = Environment.commandTitles.openAiGetModel; - description = Environment.commandDescriptions.openAiGetModel; - - async execute(msg: Message): Promise { - await replyToMessage({message: msg, text: await formatRuntimeModelInfo(AiProvider.OPENAI)}).catch(logError); +export class OpenAIGetModel extends ProviderGetModelCommand { + constructor() { + super({ + provider: AiProvider.OPENAI, + title: Environment.commandTitles.openAiGetModel, + description: Environment.commandDescriptions.openAiGetModel, + }); } } diff --git a/src/commands/openai-list-models.ts b/src/commands/openai-list-models.ts index db6bf9e..1490aa0 100644 --- a/src/commands/openai-list-models.ts +++ b/src/commands/openai-list-models.ts @@ -1,28 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {escapeHtml, logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {listProviderModels} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderListModelsCommand} from "./provider-model-command"; -export class OpenAIListModels extends Command { - title = Environment.commandTitles.openAiListModels; - description = Environment.commandDescriptions.openAiListModels; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message): Promise { - try { - const models = (await listProviderModels(AiProvider.OPENAI)).sort((a, b) => a.localeCompare(b)); - const modelsString = escapeHtml(models.join("\n").substring(0, 4000)); - const text = Environment.modelListHeaderText + "
" + modelsString + "
"; - - await replyToMessage({message: msg, text, parse_mode: "HTML"}); - } catch (e) { - logError(e); - await replyToMessage({message: msg, text: Environment.modelListLoadFailedText}).catch(logError); - } +export class OpenAIListModels extends ProviderListModelsCommand { + constructor() { + super({ + provider: AiProvider.OPENAI, + title: Environment.commandTitles.openAiListModels, + description: Environment.commandDescriptions.openAiListModels, + }); } } diff --git a/src/commands/openai-set-model.ts b/src/commands/openai-set-model.ts index 7198fe0..8946862 100644 --- a/src/commands/openai-set-model.ts +++ b/src/commands/openai-set-model.ts @@ -1,29 +1,13 @@ -import {Command} from "../base/command"; -import {Requirements} from "../base/requirements"; -import {Requirement} from "../base/requirement"; -import {Message} from "typescript-telegram-bot-api"; -import {logError, replyToMessage} from "../util/utils"; -import {AiProvider} from "../model/ai-provider"; -import {getRuntimeModel, setRuntimeModel, formatRuntimeModelInfo} from "../ai/provider-model-runtime"; import {Environment} from "../common/environment"; +import {AiProvider} from "../model/ai-provider"; +import {ProviderSetModelCommand} from "./provider-model-command"; -export class OpenAISetModel extends Command { - argsMode = "required" as const; - - title = Environment.commandTitles.openAiSetModel; - description = Environment.commandDescriptions.openAiSetModel; - - requirements = Requirements.Build(Requirement.BOT_CREATOR); - - async execute(msg: Message, match?: RegExpExecArray | null): Promise { - const newModel = match?.[3]?.trim(); - if (newModel) setRuntimeModel(AiProvider.OPENAI, newModel); - - const model = getRuntimeModel(AiProvider.OPENAI); - const text = newModel - ? Environment.getSelectedModelWithInfoText(model, await formatRuntimeModelInfo(AiProvider.OPENAI)) - : Environment.getModelIsNotSetCurrentText(model); - - await replyToMessage({message: msg, text}).catch(logError); +export class OpenAISetModel extends ProviderSetModelCommand { + constructor() { + super({ + provider: AiProvider.OPENAI, + title: Environment.commandTitles.openAiSetModel, + description: Environment.commandDescriptions.openAiSetModel, + }); } } diff --git a/src/commands/quote.ts b/src/commands/quote.ts index 32a9399..82dca5f 100644 --- a/src/commands/quote.ts +++ b/src/commands/quote.ts @@ -21,6 +21,9 @@ import {enqueueTelegramApiCall} from "../util/telegram-api-queue"; import {AsyncSemaphore} from "../util/async-lock"; import {Environment} from "../common/environment"; import {getLruMapValue, setLruMapValue} from "../util/lru-map"; +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("command:quote"); try { GlobalFonts.registerFromPath("./assets/Inter_18pt-Thin.ttf", "InterThin"); @@ -54,6 +57,8 @@ export class Quote extends Command { if (!reply) return; try { + const startedAt = Date.now(); + logger.debug("execute.start", {chatId, messageId: msg.message_id, replyMessageId: reply.message_id}); const quoteRaw = (msg.quote?.text ?? reply.text ?? reply.caption ?? "").trim(); if (quoteRaw.length === 0) { await replyToMessage({message: msg, text: Environment.quoteMissingTextText}).catch(logError); @@ -74,7 +79,8 @@ export class Quote extends Command { }, }), {method: "sendPhoto", chatId, chatType: msg.chat.type} - ).catch(logError); + ); + logger.debug("execute.done", {chatId, messageId: msg.message_id, bytes: png.length, duration: logger.duration(startedAt)}); } catch (e) { logError(e); await replyToMessage({message: msg, text: Environment.quoteBuildFailedText}).catch(logError); @@ -146,14 +152,14 @@ async function loadCustomEmoji(customEmojiId: string): Promiseimg, cx, y, emojiSize, emojiSize); } } catch (e) { - console.warn("Failed to draw custom emoji:", e); + logger.warn("custom_emoji.draw_failed", {error: e}); try { const img = await loadEmoji("😥"); diff --git a/src/common/environment.ts b/src/common/environment.ts index 10d1c53..fa8397b 100644 --- a/src/common/environment.ts +++ b/src/common/environment.ts @@ -2,6 +2,7 @@ import fs from "node:fs"; import path from "node:path"; import {parse as parseDotEnv} from "dotenv"; import {z} from "zod"; +import {appLogger} from "../logging/logger"; import {saveData} from "../db/database"; import {Answers} from "../model/answers"; @@ -1851,7 +1852,7 @@ export class Environment { Environment.lastRankerToolPromptMtimeMs = rankerToolPromptMtimeMs; } } catch (e) { - console.error("Failed to reload runtime environment config", e); + appLogger.child("environment").error("runtime_reload.failed", {error: e}); } } diff --git a/src/common/localization.ts b/src/common/localization.ts index f1feb35..3ad7431 100644 --- a/src/common/localization.ts +++ b/src/common/localization.ts @@ -1,6 +1,9 @@ import {AsyncLocalStorage} from "node:async_hooks"; import fs from "node:fs"; import path from "node:path"; +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("localization"); export const DEFAULT_LOCALE = "en"; export const DEFAULT_LANGUAGE_CHOICE = "default"; @@ -235,7 +238,7 @@ export class Localization { try { bundles.set(locale, JSON.parse(fs.readFileSync(filePath, "utf8")) as LocalizationBundle); } catch (e) { - console.error(`Failed to load localization file ${filePath}`, e); + logger.error("file_load.failed", {filePath, locale, error: e}); const previous = Localization.bundles.get(locale); if (previous) bundles.set(locale, previous); } @@ -244,8 +247,9 @@ export class Localization { Localization.bundles = bundles; Localization.fileMtimeMs = mtimes; Localization.fileSignature = signature; + logger.debug("reload.done", {force, locales: [...bundles.keys()]}); } catch (e) { - console.error("Failed to reload localization files", e); + logger.error("reload.failed", {error: e}); } } } diff --git a/src/db/message-dao.ts b/src/db/message-dao.ts index cf5e263..7e75e5f 100644 --- a/src/db/message-dao.ts +++ b/src/db/message-dao.ts @@ -4,12 +4,13 @@ import {StoredMessage} from "../model/stored-message"; import {and, eq} from "drizzle-orm"; import {inArray} from "drizzle-orm/sql/expressions/conditions"; import {Dao} from "../base/dao"; +import {appLogger} from "../logging/logger"; import {buildExcludedSet} from "../util/utils"; import {StoredAttachment} from "../model/stored-attachment"; export class MessageDao extends Dao { - private tag: string = "MessageDao"; + private readonly logger = appLogger.child("dao:messages"); override async getAll(): Promise { await DatabaseManager.ready; @@ -19,7 +20,7 @@ export class MessageDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getAll()`, `took ${diff}ms; size: ${messages.length}`); + this.logger.trace("get_all", {dao: "messages", duration: `${diff}ms`, size: messages.length}); return this.mapFrom(messages); } @@ -40,7 +41,7 @@ export class MessageDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getById(${params.chatId}, ${params.id})`, `took ${diff}ms; size: ${messages.length}`); + this.logger.trace("get_by_id", {dao: "messages", chatId: params.chatId, id: params.id, duration: `${diff}ms`, size: messages.length}); const m = messages[0]; if (!m) return null; @@ -63,7 +64,7 @@ export class MessageDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getByIds(${params.chatId}, ${params.ids})`, `took ${diff}ms; size: ${messages.length}`); + this.logger.trace("get_by_ids", {dao: "messages", chatId: params.chatId, ids: params.ids, duration: `${diff}ms`, size: messages.length}); return this.mapFrom(messages); } @@ -83,7 +84,7 @@ export class MessageDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: insert(size: ${values.length})`, `took ${diff}ms'; inserted: ${r.rowsAffected}`); + this.logger.debug("insert", {dao: "messages", duration: `${diff}ms`, size: values.length, rowsAffected: r.rowsAffected}); return true; } diff --git a/src/db/user-dao.ts b/src/db/user-dao.ts index e969968..3d7a056 100644 --- a/src/db/user-dao.ts +++ b/src/db/user-dao.ts @@ -1,5 +1,6 @@ import {StoredUser} from "../model/stored-user"; import {Dao} from "../base/dao"; +import {appLogger} from "../logging/logger"; import {DatabaseManager} from "./database-manager"; import {UserInsert, usersTable} from "./schema"; import {eq} from "drizzle-orm"; @@ -9,7 +10,7 @@ import {boolToInt, buildExcludedSet} from "../util/utils"; export class UserDao extends Dao { - private tag: string = "UserDao"; + private readonly logger = appLogger.child("dao:users"); override async getAll(): Promise { await DatabaseManager.ready; @@ -19,7 +20,7 @@ export class UserDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getAll()`, `took ${diff}ms; size: ${users.length}`); + this.logger.trace("get_all", {dao: "users", duration: `${diff}ms`, size: users.length}); return this.mapFrom(users); } @@ -37,7 +38,7 @@ export class UserDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getById(${params.id})`, `took ${diff}ms; size: ${users.length}`); + this.logger.trace("get_by_id", {dao: "users", id: params.id, duration: `${diff}ms`, size: users.length}); const u = users[0]; if (!u) return null; @@ -57,7 +58,7 @@ export class UserDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: getByIds(${params.ids})`, `took ${diff}ms; size: ${users.length}`); + this.logger.trace("get_by_ids", {dao: "users", ids: params.ids, duration: `${diff}ms`, size: users.length}); return this.mapFrom(users); } @@ -78,7 +79,7 @@ export class UserDao extends Dao { const now = Date.now(); const diff = now - then; - console.log(`${this.tag}: insert(size: ${rows.length})`, `took ${diff}ms; inserted: ${r.rowsAffected}`); + this.logger.debug("insert", {dao: "users", duration: `${diff}ms`, size: rows.length, rowsAffected: r.rowsAffected}); return true; } diff --git a/src/index.ts b/src/index.ts index cba4bc1..946c18b 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,4 +1,5 @@ import "dotenv/config"; +import {appLogger} from "./logging/logger"; import {Environment} from "./common/environment"; import {BotCommand, TelegramBot, User} from "typescript-telegram-bot-api"; import {Command} from "./base/command"; @@ -194,13 +195,15 @@ export const NOTES_HEADER = "## Notes\n"; export const notesDir = path.join(Environment.DATA_PATH, "notes"); export const notesRootFile = path.join(notesDir, "index.md"); +const logger = appLogger.child("main"); + let isShuttingDown = false; async function shutdown(signal: NodeJS.Signals) { if (isShuttingDown) return; isShuttingDown = true; - console.log(`Received ${signal}. Stopping bot polling...`); + logger.warn("shutdown.signal", {signal}); try { await bot.stopPolling(); @@ -214,27 +217,30 @@ async function shutdown(signal: NodeJS.Signals) { async function main() { const start = Date.now(); - console.log([ - `TEST_ENVIRONMENT: ${Environment.TEST_ENVIRONMENT}`, - `IS_DOCKER: ${Environment.IS_DOCKER}`, - `DATA_PATH: ${Environment.DATA_PATH}`, - `DB_PATH: ${Environment.DB_PATH}` - ].join("\n")); + logger.info("startup.config", { + testEnvironment: Environment.TEST_ENVIRONMENT, + isDocker: Environment.IS_DOCKER, + dataPath: Environment.DATA_PATH, + dbPath: Environment.DB_PATH, + }); const dirsToCheck = [cacheDir, photoDir, photoGenDir, documentDir, audioDir, videoDir, videoNotesDir, videoTempDir, notesDir]; dirsToCheck.forEach(dir => { if (!fs.existsSync(dir)) { fs.mkdirSync(dir, {recursive: true}); + logger.debug("startup.dir_created", {dir}); } }); const notesRootFilePath = path.join(notesDir, "index.md"); if (!fs.existsSync(notesRootFilePath)) { fs.writeFileSync(notesRootFilePath, "\n" + NOTES_HEADER); + logger.debug("startup.notes_root_created", {notesRootFilePath}); } if (!(fs.readFileSync(notesRootFilePath).toString().includes(NOTES_HEADER))) { fs.appendFileSync(notesRootFilePath, "\n" + NOTES_HEADER); + logger.debug("startup.notes_header_added", {notesRootFilePath}); } // TODO: 13/05/2026, Danil Nikolaev: maybe add clean cache option (or just save summarizations) @@ -245,12 +251,10 @@ async function main() { // midnight.setDate(now.getDate() + 1); // const diff = midnight.getTime() - now.getTime(); - // console.log("Clearing up cache will be started in " + diff + "ms"); // clearUpFolderFromOldFiles(cacheDir); // delay(diff).then(() => { // setInterval(() => { - // console.log("Started clearing up cache"); // clearUpFolderFromOldFiles(cacheDir); // }, 1000 * 60 * 60 * 24); // }); @@ -278,7 +282,7 @@ async function main() { const end = Date.now(); const diff = Math.abs(end - start); - console.log(`Bot started in ${diff}ms!`); + logger.success("startup.ready", {duration: `${diff}ms`, commands: cmds.length, botId: botUser.id, botUsername: botUser.username}); } catch (error) { logError(error); } diff --git a/src/util/files.ts b/src/util/files.ts index 3c080e1..22b5511 100644 --- a/src/util/files.ts +++ b/src/util/files.ts @@ -1,6 +1,9 @@ import {logError} from "./utils"; import fs from "node:fs"; import path from "node:path"; +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("files"); export function clearUpFolderFromOldFiles(folder: string, recursive = true) { fs.readdir(folder, (err, files) => { @@ -33,11 +36,16 @@ export function clearUpFolderFromOldFiles(folder: string, recursive = true) { } }); - console.log("filenamesToDelete", filenamesToDelete); + logger.debug("cleanup.candidates", {folder, recursive, count: filenamesToDelete.length, filenamesToDelete}); if (filenamesToDelete.length) { filenamesToDelete.forEach((filename) => { fs.rm(filename, (e) => { - if (e) logError(e); + if (e) { + logger.error("cleanup.delete_failed", {filename, error: e}); + logError(e); + } else { + logger.debug("cleanup.deleted", {filename}); + } }); }); } diff --git a/src/util/shell-command-runner.ts b/src/util/shell-command-runner.ts index 20907ae..d2ba38b 100644 --- a/src/util/shell-command-runner.ts +++ b/src/util/shell-command-runner.ts @@ -1,7 +1,9 @@ import {exec} from "node:child_process"; import {promisify} from "node:util"; +import {appLogger} from "../logging/logger"; const execAsync = promisify(exec); +const logger = appLogger.child("shell-command-runner"); export type ShellCommandResult = { stdout: string | null | undefined; @@ -60,18 +62,17 @@ export class ShellCommandRunner { maxBuffer: 64 * 1024, }); if (stdout) { - console.log("COMMAND: ", command, "\n", "Output:", stdout); + logger.debug("command.stdout", {command, stdout}); } if (stderr) { - console.error("COMMAND: ", command, "\n", "Error:", stderr); + logger.warn("command.stderr", {command, stderr}); } return {stdout, stderr}; } catch (error: unknown) { const err = error as Partial; - console.error("Error code:", err.code); - console.error("Stderr:", err.stderr); + logger.error("command.failed", {command, code: err.code, stderr: err.stderr, error}); return {stdout: err.stdout ?? null, stderr: err.stderr ?? err.message ?? String(error)}; } diff --git a/src/util/telegram-api-queue.ts b/src/util/telegram-api-queue.ts index dd3fa72..5b82fe3 100644 --- a/src/util/telegram-api-queue.ts +++ b/src/util/telegram-api-queue.ts @@ -11,6 +11,10 @@ * queue always honors `parameters.retry_after` and requeues the task. */ +import {appLogger} from "../logging/logger"; + +const logger = appLogger.child("telegram-api-queue"); + export type TelegramChatId = number | string; export type TelegramChatType = string; @@ -345,6 +349,7 @@ export class TelegramApiQueue { this.globalBucket = new SlidingWindowRateLimit(this.options.globalLimit); this.editBucket = new SlidingWindowRateLimit(this.options.editLimit); this.bucketIdleMs = Math.max(this.options.perChatLimit.intervalMs, this.options.groupChatLimit.intervalMs) * 2; + logger.debug("created", {maxConcurrent: this.options.maxConcurrent, maxAttempts: this.options.maxAttempts, maxQueueSize: this.options.maxQueueSize}); } get stats(): TelegramApiQueueStats { @@ -356,9 +361,18 @@ export class TelegramApiQueue { } enqueue(task: TelegramApiTask, options: TelegramApiQueueTaskOptions = {}): Promise { - if (this.closed) return Promise.reject(createClosedError()); - if (this.queue.length >= this.options.maxQueueSize) return Promise.reject(createQueueOverflowError(this.options.maxQueueSize)); - if (options.signal?.aborted) return Promise.reject(createAbortError()); + if (this.closed) { + logger.warn("enqueue.rejected.closed", {method: options.method, chatId: options.chatId}); + return Promise.reject(createClosedError()); + } + if (this.queue.length >= this.options.maxQueueSize) { + logger.error("enqueue.rejected.overflow", {method: options.method, chatId: options.chatId, queued: this.queue.length, maxQueueSize: this.options.maxQueueSize}); + return Promise.reject(createQueueOverflowError(this.options.maxQueueSize)); + } + if (options.signal?.aborted) { + logger.debug("enqueue.rejected.aborted", {method: options.method, chatId: options.chatId}); + return Promise.reject(createAbortError()); + } return new Promise((resolve, reject) => { const entry: QueueEntry = { @@ -376,6 +390,7 @@ export class TelegramApiQueue { this.attachAbortHandler(entry); this.insertEntry(entry as QueueEntry); + logger.trace("enqueue.accepted", {taskId: entry.id, method: options.method, chatId: options.chatId, priority: options.priority, queued: this.queue.length, running: this.running}); this.pump(); }); } @@ -390,12 +405,14 @@ export class TelegramApiQueue { close(reason: unknown = createClosedError()): void { this.closed = true; + logger.warn("closed", {queued: this.queue.length, running: this.running, reason}); if (this.timer) { clearTimeout(this.timer); this.timer = null; } const queued = this.queue; + logger.debug("close.cancel_queued", {queued: queued.length}); this.queue = []; for (const entry of queued) { this.cleanupAbortHandler(entry); @@ -409,6 +426,7 @@ export class TelegramApiQueue { clear(reason: unknown = new Error("Telegram API queue was cleared")): void { const queued = this.queue; + logger.warn("cleared", {queued: queued.length, running: this.running, reason}); this.queue = []; for (const entry of queued) { this.cleanupAbortHandler(entry); @@ -435,6 +453,7 @@ export class TelegramApiQueue { this.cleanupAbortHandler(entry); entry.state = "cancelled"; + logger.debug("entry.cancelled", {taskId: entry.id, method: entry.options.method, chatId: entry.options.chatId}); entry.reject(createAbortError()); this.resolveIdleIfNeeded(); } @@ -456,6 +475,7 @@ export class TelegramApiQueue { } if (selection.delayMs > 0) { + logger.trace("pump.delayed", {delayMs: selection.delayMs, queued: this.queue.length, running: this.running}); this.schedule(selection.delayMs); return; } @@ -497,6 +517,7 @@ export class TelegramApiQueue { this.cleanupAbortHandler(entry); this.recordStart(entry, Date.now()); this.running++; + logger.trace("entry.started", {taskId: entry.id, method: entry.options.method, chatId: entry.options.chatId, attempt: entry.attempt, queued: this.queue.length, running: this.running}); void this.runEntry(entry); } @@ -509,6 +530,7 @@ export class TelegramApiQueue { signal: entry.options.signal, }); entry.state = "settled"; + logger.trace("entry.settled", {taskId: entry.id, method: entry.options.method, chatId: entry.options.chatId, attempt: entry.attempt}); entry.resolve(result); } catch (error) { const retry = this.getRetryDecision(error, entry); @@ -523,6 +545,7 @@ export class TelegramApiQueue { } else { this.attachAbortHandler(entry); this.insertEntry(entry); + logger.warn("entry.retry", {taskId: entry.id, method: entry.options.method, chatId: entry.options.chatId, attempt: entry.attempt - 1, delayMs: retry.delayMs, reason: retry.reason, error}); this.options.onRetry?.({ taskId: entry.id, method: entry.options.method, @@ -535,6 +558,7 @@ export class TelegramApiQueue { } } else { entry.state = "settled"; + logger.error("entry.failed", {taskId: entry.id, method: entry.options.method, chatId: entry.options.chatId, attempt: entry.attempt, error}); entry.reject(this.closed ? createClosedError() : error); } } finally { diff --git a/src/util/utils.ts b/src/util/utils.ts index 7c40089..d5c9e2d 100644 --- a/src/util/utils.ts +++ b/src/util/utils.ts @@ -1,5 +1,5 @@ import * as si from "systeminformation"; -import {redactLogValue} from "../ai/ai-logger"; +import {appLogger} from "../logging/logger"; import {Command} from "../base/command"; import {CallbackCommand} from "../base/callback-command"; import { @@ -49,6 +49,9 @@ import {ShellCommandResult, ShellCommandRunner} from "./shell-command-runner"; const imageProcessingSemaphore = new AsyncSemaphore(2); const fileWriteLocks = new KeyedAsyncLock(); +const logger = appLogger.child("utils"); +const requirementLogger = appLogger.child("requirements"); +const messageLogger = appLogger.child("messages"); export const ignore = () => { }; @@ -66,7 +69,7 @@ export const ignoreIfMarkupFailed = (e: Error | TelegramError) => { }; export const logError = (e: Error | TelegramError | string | unknown) => { - console.error(redactLogValue(e)); + appLogger.error("error", {error: e}); }; export const errorPlaceholder = async (msg: Message) => { @@ -148,7 +151,7 @@ export async function checkRequirements(cmd: Command | CallbackCommand | null, m !Environment.CHAT_IDS_WHITELIST.has(chatId) && !Environment.ADMIN_IDS.has(chatId) && !Environment.ADMIN_IDS.has(fromId)) { - console.log(`${title}: chatId whitelist ignored.`); + requirementLogger.debug("rejected.chat_whitelist", {title, chatId, fromId}); return false; } @@ -172,19 +175,19 @@ export async function checkRequirements(cmd: Command | CallbackCommand | null, m }; if (reqs.isRequiresBotCreator() && fromId !== Environment.CREATOR_ID) { - console.log(`${title}: creatorId is bad`); + requirementLogger.debug("rejected.creator", {title, fromId}); await notifyUser(Environment.notBotCreatorText); return false; } if (reqs.isRequiresBotAdmin() && !Environment.ADMIN_IDS.has(fromId)) { - console.log(`${title}: adminId is bad`); + requirementLogger.debug("rejected.bot_admin", {title, fromId}); await notifyUser(Environment.notBotAdministratorText); return false; } if (reqs.isRequiresChat() && msg?.chat?.type === "private") { - console.log(`${title}: chatId is bad`); + requirementLogger.debug("rejected.chat_required", {title, chatId, chatType}); await notifyUser(Environment.notAChatText); return false; } @@ -193,7 +196,7 @@ export async function checkRequirements(cmd: Command | CallbackCommand | null, m const member = await bot.getChatMember({chat_id: chatId, user_id: fromId}); if (!isMemberAdmin(member)) { - console.log(`${title}: chatAdminId is bad`); + requirementLogger.debug("rejected.chat_admin", {title, chatId, fromId}); await notifyUser(Environment.notChatAdministratorText); return false; } @@ -203,14 +206,14 @@ export async function checkRequirements(cmd: Command | CallbackCommand | null, m const member = await bot.getChatMember({chat_id: chatId, user_id: botUser.id}); if (!isMemberAdmin(member)) { - console.log(`${title}: botChatAdminId is bad`); + requirementLogger.debug("rejected.bot_chat_admin", {title, chatId}); await notifyUser(Environment.botNotChatAdministratorText); return false; } } if (reqs.isRequiresReply() && !msg?.reply_to_message) { - console.log(`${title}: replyMessage is bad`); + requirementLogger.debug("rejected.reply_required", {title, chatId, messageId}); await notifyUser(Environment.replyRequiredText); return false; } @@ -242,7 +245,7 @@ export async function checkRequirements(cmd: Command | CallbackCommand | null, m } if (!originalFromId || (fromId !== originalFromId && fromId !== Environment.CREATOR_ID)) { - console.log(`${title}: sameUser is bad`); + requirementLogger.debug("rejected.same_user", {title, chatId, fromId, originalFromId}); await notifyUser(Environment.onlyOriginalAuthorText); return false; } @@ -2090,19 +2093,23 @@ export function photoPathByUniqueId(uniqueId: string): string { } export async function processMyChatMember(u: ChatMemberUpdated): Promise { - console.log("my_chat_member", u); + messageLogger.debug("my_chat_member", {update: u}); } export async function processGuestMessage(msg: Message): Promise { // return processNewMessage(msg, true); - console.log("NEW_GUEST_MESSAGE", msg); + messageLogger.debug("guest_message.received", {message: msg}); } export async function processNewMessage(msg: Message, isGuest?: boolean): Promise { - console.log(isGuest ? "NEW_GUEST_MESSAGE" : "NEW_MESSAGE", msg); + messageLogger.debug(isGuest ? "guest_message.received" : "message.received", {message: msg}); - if (!msg.from) return; + if (!msg.from) { + messageLogger.debug("message.skipped.no_sender", {chatId: msg.chat?.id, messageId: msg.message_id}); + return; + } + const startedAt = Date.now(); const from = msg.from; Environment.reloadRuntimeConfigIfChanged(); @@ -2115,6 +2122,7 @@ export async function processNewMessage(msg: Message, isGuest?: boolean): Promis UserStore.put(from) ] ); + messageLogger.debug("message.persisted", {chatId: msg.chat.id, messageId: msg.message_id, fromId: from.id, duration: logger.duration(startedAt)}); storedMsg = results[0]; locale = await resolveInterfaceLocaleForUser(from.id, from.language_code); @@ -2193,7 +2201,15 @@ export async function processNewMessage(msg: Message, isGuest?: boolean): Promis const hasAudioAttachment = !!msg.voice || !!msg.audio || !!msg.document?.mime_type?.startsWith("audio/") || !!msg.video_note; const hasImageAttachment = !!msg.photo?.length || !!msg.document?.mime_type?.startsWith("image/"); - if (executed || (!cmdText && !hasAudioAttachment && !hasImageAttachment)) return; + if (executed) { + messageLogger.debug("message.command_executed", {chatId: msg.chat.id, messageId: msg.message_id, command: cmd?.title}); + return; + } + + if (!cmdText && !hasAudioAttachment && !hasImageAttachment) { + messageLogger.debug("message.skipped.empty", {chatId: msg.chat.id, messageId: msg.message_id}); + return; + } const hasConfiguredPrefix = Environment.BOT_PREFIX.length > 0; const startsWithPrefix = hasConfiguredPrefix && cmdText.toLowerCase().startsWith(Environment.BOT_PREFIX.toLowerCase()); @@ -2223,12 +2239,14 @@ export async function processNewMessage(msg: Message, isGuest?: boolean): Promis }); if (!isReplyToBot && !hasPrefix && !hasBotMention && !hasAudioAttachment) { + messageLogger.debug("message.skipped.not_addressed", {chatId: msg.chat.id, messageId: msg.message_id}); return; } } const provider = await resolveEffectiveAiProviderForUser(from.id); + messageLogger.info("ai.dispatch", {chatId: msg.chat.id, messageId: msg.message_id, fromId: from.id, provider}); void runUnifiedAi({ provider: provider, msg: msg,