From 6c57e6fcc33334fc03d83b0b44001d5436ffecd6 Mon Sep 17 00:00:00 2001 From: Alireza Safaierad Date: Mon, 3 Aug 2026 11:26:37 +0200 Subject: [PATCH] feat: add structured logging --- .env.example | 9 ++- .gitignore | 2 + cspell-words.txt | 1 + docker-compose.yaml | 1 + eslint.config.ts | 11 +++- package.json | 4 ++ pnpm-lock.yaml | 92 +++++++++++++++++++++++++++ src/api.ts | 6 +- src/bot/bot.ts | 5 ++ src/bot/middleware/logger.ts | 82 ++++++++++-------------- src/config/index.ts | 11 ++++ src/index.ts | 4 +- src/lib/github/webhooks/index.ts | 22 +++++++ src/lib/github/webhooks/report.ts | 23 +++++-- src/lib/github/webhooks/withGuards.ts | 11 +++- src/lib/logger/format.spec.ts | 50 +++++++++++++++ src/lib/logger/format.ts | 87 +++++++++++++++++++++++++ src/lib/logger/index.ts | 52 +++++++++++++++ src/lib/logger/telegram-stream.ts | 57 +++++++++++++++++ src/lib/telegram/createCommand.ts | 14 +++- tsconfig.json | 1 + 21 files changed, 476 insertions(+), 69 deletions(-) create mode 100644 src/lib/logger/format.spec.ts create mode 100644 src/lib/logger/format.ts create mode 100644 src/lib/logger/index.ts create mode 100644 src/lib/logger/telegram-stream.ts diff --git a/.env.example b/.env.example index f2621b8..f4d9451 100644 --- a/.env.example +++ b/.env.example @@ -22,10 +22,15 @@ BOT_POLLING=false ## GitHub Application variables #Personal GitHub token GITHUB_TOKEN= -## GitHub organization to receive events from +## GitHub organization to receive events from GITHUB_ORG_NAME=fullstacksjs ## Shared secret for GitHub webhook GITHUB_WEBHOOK_SECRET= # Database variables -DB_FILE_PATH="file:database.sqlite" \ No newline at end of file +DB_FILE_PATH="file:database.sqlite" + +# Logger variables +LOG_LEVEL=info +LOG_FILE_PATH="logs/app.log" +LOG_TELEGRAM_LEVEL=info diff --git a/.gitignore b/.gitignore index d654a2d..34370c5 100644 --- a/.gitignore +++ b/.gitignore @@ -4,3 +4,5 @@ node_modules/ !.env.example *.sqlite + +logs/ diff --git a/cspell-words.txt b/cspell-words.txt index 2f92256..570335d 100644 --- a/cspell-words.txt +++ b/cspell-words.txt @@ -10,6 +10,7 @@ libsql listcontributors listrepos lyja +multistream nodenext pipefail removerepo diff --git a/docker-compose.yaml b/docker-compose.yaml index f39550c..5ec8cd4 100644 --- a/docker-compose.yaml +++ b/docker-compose.yaml @@ -8,4 +8,5 @@ services: - .env volumes: - ./data:/app/data + - ./logs:/app/logs restart: on-failure:16 diff --git a/eslint.config.ts b/eslint.config.ts index 337df69..b67768f 100644 --- a/eslint.config.ts +++ b/eslint.config.ts @@ -1,3 +1,12 @@ import { defineConfig } from "@fullstacksjs/eslint-config"; -export default defineConfig({ esm: true, node: true, strict: true }); +export default defineConfig({ + esm: true, + node: true, + strict: true, + rules: { + "@typescript-eslint/no-unsafe-call": "off", + "@typescript-eslint/no-unsafe-member-access": "off", + "@typescript-eslint/no-unsafe-assignment": "off", + }, +}); diff --git a/package.json b/package.json index 308b243..d5b2d19 100644 --- a/package.json +++ b/package.json @@ -16,6 +16,9 @@ "#github": [ "./src/lib/github/index.ts" ], + "#logger": [ + "./src/lib/logger/index.ts" + ], "#webhooks": [ "./src/lib/github/webhooks/index.ts" ], @@ -52,6 +55,7 @@ "grammy": "1.38.3", "hono": "4.10.6", "octokit": "5.0.5", + "pino": "10.3.1", "zod": "4.1.12" }, "devDependencies": { diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index c3ae749..2235168 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -50,6 +50,9 @@ importers: octokit: specifier: 5.0.5 version: 5.0.5 + pino: + specifier: 10.3.1 + version: 10.3.1 zod: specifier: 4.1.12 version: 4.1.12 @@ -1351,6 +1354,9 @@ packages: resolution: {integrity: sha512-gcK4FNaROM9NjA0mvyfXl0KPusk7a1BeA8ITlYEZVQCXF5gcETTd4yhAU0Kjzd8mXwYHppzJBWgdBVpIR9wUcQ==} engines: {node: '>= 20'} + '@pinojs/redact@0.4.0': + resolution: {integrity: sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==} + '@pkgr/core@0.2.9': resolution: {integrity: sha512-QNqXyfVS2wm9hweSYD2O7F0G06uurj9kZ96TRQE5Y9hU7+tgdZwIkbAKc5Ocy1HxEY2kuDQa6cQ1WRs/O5LFKA==} engines: {node: ^12.20.0 || ^14.18.0 || >=16.0.0} @@ -1927,6 +1933,10 @@ packages: resolution: {integrity: sha512-hsU18Ae8CDTR6Kgu9DYf0EbCr/a5iGL0rytQDobUcdpYOKokk8LEjVphnXkDkgpi0wYVsqrXuP0bZxJaTqdgoA==} engines: {node: '>= 0.4'} + atomic-sleep@1.0.0: + resolution: {integrity: sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==} + engines: {node: '>=8.0.0'} + available-typed-arrays@1.0.7: resolution: {integrity: sha512-wvUjBtSGN7+7SjNpq/9M2Tg350UZD3q62IFZLbRAR1bSMlCo1ZaeW+BJ+D090e4hIIZLBcTDWe4Mh4jvUDajzQ==} engines: {node: '>= 0.4'} @@ -3272,6 +3282,10 @@ packages: resolution: {integrity: sha512-4+/OFSqOjoyULo7eN7EA97DE0Xydj/PW5aIckxqQIoFjFwqXKuFCvXUJObyJfBF9Khu4RL/jlDRI9FPaMGfPnw==} engines: {node: '>= 20'} + on-exit-leak-free@2.1.2: + resolution: {integrity: sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==} + engines: {node: '>=14.0.0'} + onetime@7.0.0: resolution: {integrity: sha512-VXJjc87FScF88uafS3JllDgvAm+c/Slfz06lorj2uAY34rlUu0Nt+v8wreiImcrgAjjIHp1rXpTDlLOGw29WwQ==} engines: {node: '>=18'} @@ -3354,6 +3368,16 @@ packages: resolution: {integrity: sha512-udgsAY+fTnvv7kI7aaxbqwWNb0AHiB0qBO89PZKPkoTmGOgdbrHDKD+0B2X4uTfJ/FT1R09r9gTsjUjNJotuog==} engines: {node: '>=0.10.0'} + pino-abstract-transport@3.0.0: + resolution: {integrity: sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==} + + pino-std-serializers@7.1.0: + resolution: {integrity: sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==} + + pino@10.3.1: + resolution: {integrity: sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==} + hasBin: true + pkg-types@1.3.1: resolution: {integrity: sha512-/Jm5M4RvtBFVkKWRu2BLUTNP8/M2a+UwuAX+ae4770q1qVGtfjG+WTCupoZixokjmHiry8uI+dlY8KXYV5HVVQ==} @@ -3394,6 +3418,9 @@ packages: resolution: {integrity: sha512-Qb1gy5OrP5+zDf2Bvnzdl3jsTf1qXVMazbvCoKhtKqVs4/YK4ozX4gKQJJVyNe+cajNPn0KoC0MC3FUmaHWEmQ==} engines: {node: ^10.13.0 || ^12.13.0 || ^14.15.0 || >=15.0.0} + process-warning@5.1.0: + resolution: {integrity: sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==} + promise-limit@2.7.0: resolution: {integrity: sha512-7nJ6v5lnJsXwGprnGXga4wx6d1POjvi5Qmf1ivTRxTjH4Z/9Czja/UCMLVmB9N93GeWOU93XaFaEt6jbuoagNw==} @@ -3407,6 +3434,9 @@ packages: queue-microtask@1.2.3: resolution: {integrity: sha512-NuaNSa6flKT5JaSYQzJok04JzTL1CA6aGhv5rfLW3PgqA+M2ChpZQnAC8h8i4ZFkBS8X5RqkDBHA7r4hej3K9A==} + quick-format-unescaped@4.0.4: + resolution: {integrity: sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==} + react-dom@19.2.0: resolution: {integrity: sha512-UlbRu4cAiGaIewkPyiRGJk0imDN2T3JjieT6spoL2UeSf5od4n5LB/mQ4ejmxhCFT1tYe8IvaFulzynWovsEFQ==} peerDependencies: @@ -3422,6 +3452,13 @@ packages: read-cache@1.0.0: resolution: {integrity: sha512-Owdv/Ft7IjOgm/i0xvNDZ1LrRANRfew4b2prF3OWMQLxLfu3bS8FVhCsrSCMK4lR56Y9ya+AThoTpDCTxCmpRA==} + real-require@0.2.0: + resolution: {integrity: sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==} + engines: {node: '>= 12.13.0'} + + real-require@1.0.0: + resolution: {integrity: sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==} + recast@0.23.11: resolution: {integrity: sha512-YTUo+Flmw4ZXiWfQKGcwwc11KnoRAYgzAE2E7mXKCjSviTKShtxBsN6YUUBB2gtaBzKzeKunxhUwNHQuRryhWA==} engines: {node: '>= 4'} @@ -3501,6 +3538,10 @@ packages: resolution: {integrity: sha512-x/+Cz4YrimQxQccJf5mKEbIa1NzeCRNI5Ecl/ekmlYaampdNLPalVyIcCZNNH3MvmqBugV5TMYZXv0ljslUlaw==} engines: {node: '>= 0.4'} + safe-stable-stringify@2.5.0: + resolution: {integrity: sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==} + engines: {node: '>=10'} + scheduler@0.27.0: resolution: {integrity: sha512-eNv+WrVbKu1f3vbYJT/xtiF5syA5HPIMtf9IgY/nKg0sWqzAUEvqY/xm7OcZc/qafLx/iO9FgOmeSAp4v5ti/Q==} @@ -3577,6 +3618,9 @@ packages: resolution: {integrity: sha512-QlaZEqcAH3/RtNyet1IPIYPsEWAaYyXXv1Krsi+1L/QHppjX4Ifm8MQsBISz9vE8cHicIq3clogsheili5vhaQ==} engines: {node: '>= 18'} + sonic-boom@4.2.1: + resolution: {integrity: sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==} + source-map-js@1.2.1: resolution: {integrity: sha512-UXWMKhLOwVKb728IUtQPXxfYU+usdybtUrK/8uGE8CQMvrhOpwvzDBwj0QhSL7MQc7vIsISBG8VQ8+IDQxpfQA==} engines: {node: '>=0.10.0'} @@ -3697,6 +3741,10 @@ packages: resolution: {integrity: sha512-te/NtwBwfiNRLf9Ijqx3T0nlqZiQ2XrrtBvu+cLL8ZRrGkO0NHTug8MYFKyoSrv/sHTaSKfilUkizV6XhxMJ3g==} engines: {node: '>=8'} + thread-stream@4.2.0: + resolution: {integrity: sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==} + engines: {node: '>=20'} + through@2.3.8: resolution: {integrity: sha512-w89qg7PI8wAdvX60bMDP+bFoD5Dvhm9oLheFp5O4a2QF0cSBGsBX4qZmadPMvVqlLJBBci+WqGGOAPvcDeNSVg==} @@ -5242,6 +5290,8 @@ snapshots: '@octokit/request-error': 7.0.1 '@octokit/webhooks-methods': 6.0.0 + '@pinojs/redact@0.4.0': {} + '@pkgr/core@0.2.9': {} '@rollup/rollup-android-arm-eabi@4.53.5': @@ -5840,6 +5890,8 @@ snapshots: async-function@1.0.0: {} + atomic-sleep@1.0.0: {} + available-typed-arrays@1.0.7: dependencies: possible-typed-array-names: 1.1.0 @@ -7334,6 +7386,8 @@ snapshots: '@octokit/types': 16.0.0 '@octokit/webhooks': 14.1.3 + on-exit-leak-free@2.1.2: {} + onetime@7.0.0: dependencies: mimic-function: 5.0.1 @@ -7406,6 +7460,26 @@ snapshots: pify@2.3.0: {} + pino-abstract-transport@3.0.0: + dependencies: + split2: 4.2.0 + + pino-std-serializers@7.1.0: {} + + pino@10.3.1: + dependencies: + '@pinojs/redact': 0.4.0 + atomic-sleep: 1.0.0 + on-exit-leak-free: 2.1.2 + pino-abstract-transport: 3.0.0 + pino-std-serializers: 7.1.0 + process-warning: 5.1.0 + quick-format-unescaped: 4.0.4 + real-require: 0.2.0 + safe-stable-stringify: 2.5.0 + sonic-boom: 4.2.1 + thread-stream: 4.2.0 + pkg-types@1.3.1: dependencies: confbox: 0.1.8 @@ -7449,6 +7523,8 @@ snapshots: ansi-styles: 5.2.0 react-is: 17.0.2 + process-warning@5.1.0: {} + promise-limit@2.7.0: {} punycode@2.3.1: {} @@ -7457,6 +7533,8 @@ snapshots: queue-microtask@1.2.3: {} + quick-format-unescaped@4.0.4: {} + react-dom@19.2.0(react@19.2.0): dependencies: react: 19.2.0 @@ -7470,6 +7548,10 @@ snapshots: dependencies: pify: 2.3.0 + real-require@0.2.0: {} + + real-require@1.0.0: {} + recast@0.23.11: dependencies: ast-types: 0.16.1 @@ -7588,6 +7670,8 @@ snapshots: es-errors: 1.3.0 is-regex: 1.2.1 + safe-stable-stringify@2.5.0: {} + scheduler@0.27.0: {} scslre@0.3.0: @@ -7674,6 +7758,10 @@ snapshots: smol-toml@1.5.2: {} + sonic-boom@4.2.1: + dependencies: + atomic-sleep: 1.0.0 + source-map-js@1.2.1: {} source-map-support@0.5.21: @@ -7804,6 +7892,10 @@ snapshots: text-extensions@2.4.0: {} + thread-stream@4.2.0: + dependencies: + real-require: 1.0.0 + through@2.3.8: {} tiny-invariant@1.3.3: {} diff --git a/src/api.ts b/src/api.ts index d75cfc4..6677465 100644 --- a/src/api.ts +++ b/src/api.ts @@ -32,9 +32,7 @@ export async function createApi() { }); if (!payload.success) { - // eslint-disable-next-line no-console - console.error("Invalid payload:", payload.error); - await reportWebhookError(payload.error, { + reportWebhookError(payload.error, { eventId: deliveryId, eventName, source: "request_validation", @@ -45,7 +43,7 @@ export async function createApi() { try { await webhooks.verifyAndReceive(payload.data); } catch (error) { - await reportWebhookError(error, { + reportWebhookError(error, { eventId: payload.data.id, eventName: payload.data.name, source: "request_processing", diff --git a/src/bot/bot.ts b/src/bot/bot.ts index 5f2f83b..91e04d1 100644 --- a/src/bot/bot.ts +++ b/src/bot/bot.ts @@ -5,6 +5,7 @@ import { autoRetry } from "@grammyjs/auto-retry"; import { I18n } from "@grammyjs/i18n"; import { limit } from "@grammyjs/ratelimiter"; import { config } from "#config"; +import { botLogger } from "#logger"; import { Bot as GrammyBot } from "grammy"; import type { HelperContext } from "./middleware/helpers.ts"; @@ -90,6 +91,10 @@ export class Bot extends GrammyBot { this.filter(isAdmin).use(adminCommands); this.api.config.use(autoRetry({ maxRetryAttempts: 2 })); + + this.catch(({ error, ctx }) => { + botLogger.error({ err: error, updateId: ctx.update.update_id, chatId: ctx.chat?.id }, "unhandled bot error"); + }); } /** diff --git a/src/bot/middleware/logger.ts b/src/bot/middleware/logger.ts index 4c4114c..7a411c1 100644 --- a/src/bot/middleware/logger.ts +++ b/src/bot/middleware/logger.ts @@ -1,63 +1,51 @@ -/* eslint-disable no-console */ import type { BotContext } from "#bot"; -import { config } from "#config"; +import { botLogger } from "#logger"; import { GrammyError } from "grammy"; import { formatErrorDetails } from "../../lib/error-details.ts"; import { escapeHtml } from "../../lib/escape-html.ts"; -import { sendReport } from "../../lib/telegram/report.ts"; + +function buildErrorReport(ctx: BotContext, error: unknown): string { + const update = ctx.update.message; + const command = update?.text ? escapeHtml(update.text) : "N/A"; + const firstName = update?.from?.first_name ? escapeHtml(update.from.first_name) : "Unknown"; + const link = update?.from?.username + ? `@${escapeHtml(update.from.username)}` + : `${firstName}`; + + const details = error instanceof GrammyError ? error.description : formatErrorDetails(error); + + return [ + `Command: ${command}`, + `Sender Name: ${link}`, + "", + "Message:", + "", + `
${escapeHtml(details)}
`, + ].join("\n"); +} export const logger = async (ctx: BotContext, next: () => Promise) => { - ctx.logger = { - log: async (message: string) => { - console.log(message); - return sendReport(ctx.api, message); - }, - error: async (message: string) => { - console.log("Report for", config.bot.reportChatId); - - console.error(message); - return sendReport(ctx.api, message); - }, + ctx.logger = botLogger.child({ + updateId: ctx.update.update_id, + chatId: ctx.chat?.id, + userId: ctx.from?.id, + username: ctx.from?.username, + }); + + ctx.report = (error: unknown) => { + ctx.logger.error({ err: error, tg: buildErrorReport(ctx, error) }, "command failed"); }; - ctx.report = async (e: unknown) => { - let message = ""; - const update = ctx.update.message; - const command = update?.text ? escapeHtml(update.text) : "N/A"; - const firstName = update?.from?.first_name ? escapeHtml(update.from.first_name) : "Unknown"; - const link = update?.from.username - ? `@${escapeHtml(update.from.username)}` - : `${firstName}`; - - message += [ - "Error:", - `Command: ${command}`, - `Sender Name: ${link}`, - "", - "Message:", - "", - ].join("\n"); - - if (e instanceof GrammyError) { - message += `
${escapeHtml(e.description)}
\n`; - } else { - message += `
${escapeHtml(formatErrorDetails(e))}
\n`; - } - - message += `\n#error`; - - return ctx.logger.error(message); - }; + ctx.logger.debug({ text: ctx.update.message?.text }, "update received"); return next(); }; export interface LoggerContext { - logger: { - log: (log: string) => Promise | undefined; - error: (error: string) => Promise | undefined; - }; - report: (error: unknown) => Promise | undefined; + /** Logger bound to the current update. */ + logger: typeof botLogger; + /** Reports an error to the log file and the Telegram debug chat. */ + report: (error: unknown) => void; } diff --git a/src/config/index.ts b/src/config/index.ts index b2011b3..7d807fc 100644 --- a/src/config/index.ts +++ b/src/config/index.ts @@ -27,6 +27,12 @@ const schema = new Config({ database: Config.object({ filePath: Config.string({ default: "file:database.sqlite" }), }), + + logger: Config.object({ + level: Config.string({ default: "info" }), + filePath: Config.string({ default: "logs/app.log" }), + telegramLevel: Config.string({ default: "info" }), + }), }); export const config = schema @@ -52,5 +58,10 @@ export const config = schema database: { filePath: env.DB_FILE_PATH, }, + logger: { + level: env.LOG_LEVEL, + filePath: env.LOG_FILE_PATH, + telegramLevel: env.LOG_TELEGRAM_LEVEL, + }, }) .getAll(); diff --git a/src/index.ts b/src/index.ts index 58807ce..e47a8cf 100644 --- a/src/index.ts +++ b/src/index.ts @@ -1,11 +1,11 @@ import { serve } from "@hono/node-server"; import { bot } from "#bot"; import { config } from "#config"; +import { apiLogger } from "#logger"; import { createApi } from "./api.ts"; const api = await createApi(); await bot.run(); serve({ fetch: api.fetch, port: config.api.port }); -// eslint-disable-next-line no-console -console.log(`API is listening on port ${config.api.port}`); +apiLogger.info({ port: config.api.port, mode: config.bot.polling ? "polling" : "webhook" }, "api listening"); diff --git a/src/lib/github/webhooks/index.ts b/src/lib/github/webhooks/index.ts index b01e180..29b1b50 100644 --- a/src/lib/github/webhooks/index.ts +++ b/src/lib/github/webhooks/index.ts @@ -1,5 +1,6 @@ import { Webhooks } from "@octokit/webhooks"; import { config } from "#config"; +import { githubLogger } from "#logger"; import { commentCreatedCallback } from "./handlers/comment-created.ts"; import { issuesAssignedCallback } from "./handlers/issues-assigned.ts"; @@ -15,6 +16,27 @@ import { withGuards } from "./withGuards.ts"; export const webhooks = new Webhooks({ secret: config.github.webhookSecret }); +interface AnyPayload { + action?: string; + repository?: { full_name?: string }; + sender?: { login?: string }; +} + +webhooks.onAny(({ id, name, payload }) => { + const { action, repository, sender } = payload as AnyPayload; + + githubLogger.info( + { + deliveryId: id, + event: action ? `${name}.${action}` : name, + repo: repository?.full_name, + sender: sender?.login, + tags: ["webhook"], + }, + "webhook received", + ); +}); + webhooks.on("issues.assigned", withGuards(issuesAssignedCallback)); webhooks.on("issues.opened", withGuards(issuesOpenedCallback)); webhooks.on("pull_request.closed", withGuards(pullRequestClosedCallback)); diff --git a/src/lib/github/webhooks/report.ts b/src/lib/github/webhooks/report.ts index 8a147f0..40f3d64 100644 --- a/src/lib/github/webhooks/report.ts +++ b/src/lib/github/webhooks/report.ts @@ -1,9 +1,7 @@ -/* eslint-disable no-console */ -import { bot } from "#bot"; +import { githubLogger } from "#logger"; import { formatErrorDetails } from "../../error-details.ts"; import { escapeHtml } from "../../escape-html.ts"; -import { sendReport } from "../../telegram/report.ts"; const reportedWebhookError = Symbol("reportedWebhookError"); @@ -59,16 +57,27 @@ export function buildWebhookErrorReport(error: unknown, context: WebhookReportCo if (eventId) lines.push(`Delivery: ${escapeHtml(eventId)}`); if (context.source) lines.push(`Source: ${escapeHtml(context.source)}`); - lines.push("", "Message:", "", `
${escapeHtml(formatErrorDetails(error))}
`, "", "#webhook #error"); + lines.push("", "Message:", "", `
${escapeHtml(formatErrorDetails(error))}
`); return lines.join("\n"); } -export async function reportWebhookError(error: unknown, context: WebhookReportContext = {}) { +export function reportWebhookError(error: unknown, context: WebhookReportContext = {}) { if (hasReportedWebhookError(error)) return; markWebhookErrorReported(error); - console.error(error); - return sendReport(bot.api, buildWebhookErrorReport(error, context)); + const event = getEventInfo(error); + + githubLogger.error( + { + err: error, + deliveryId: context.eventId ?? event.eventId, + event: context.eventName ?? event.eventName, + source: context.source, + tags: ["webhook"], + tg: buildWebhookErrorReport(error, context), + }, + "webhook failed", + ); } diff --git a/src/lib/github/webhooks/withGuards.ts b/src/lib/github/webhooks/withGuards.ts index 247f6df..66d3cbc 100644 --- a/src/lib/github/webhooks/withGuards.ts +++ b/src/lib/github/webhooks/withGuards.ts @@ -1,5 +1,7 @@ import type { EmitterWebhookEvent, EmitterWebhookEventName, HandlerFunction } from "@octokit/webhooks/types"; +import { githubLogger } from "#logger"; + import { isRepositoryAccepted, isUserMuted } from "./handlers/_utils.ts"; /** @@ -38,17 +40,20 @@ export function withGuards( ) { return async (event: EmitterWebhookEvent) => { const username = event.payload.sender?.login; + const skipped = (reason: string, details: Record = {}) => { + githubLogger.debug({ deliveryId: event.id, event: event.name, reason, ...details }, "webhook skipped"); + }; if (!options.skipRepositoryCheck) { - if (!("repository" in event.payload)) return; + if (!("repository" in event.payload)) return skipped("no_repository"); const repo = event.payload.repository?.full_name; if (repo && !(await isRepositoryAccepted(repo))) { - return; + return skipped("repository_blacklisted", { repo }); } } - if (username && (await isUserMuted(username))) return; + if (username && (await isUserMuted(username))) return skipped("user_muted", { sender: username }); // eslint-disable-next-line @typescript-eslint/no-unsafe-return return handler(event); diff --git a/src/lib/logger/format.spec.ts b/src/lib/logger/format.spec.ts new file mode 100644 index 0000000..a342d00 --- /dev/null +++ b/src/lib/logger/format.spec.ts @@ -0,0 +1,50 @@ +import { levels } from "pino"; +import { describe, expect, it } from "vitest"; + +import type { LogRecord } from "./format.ts"; + +import { formatLogForTelegram } from "./format.ts"; + +function record(overrides: Partial = {}): LogRecord { + return { level: levels.values.info, time: 0, ...overrides }; +} + +describe("formatLogForTelegram", () => { + it("renders the level, scope and message", () => { + const message = formatLogForTelegram(record({ scope: "bot", msg: "command received" })); + + expect(message).toContain("INFO Ā· bot"); + expect(message).toContain("command received"); + expect(message).toContain("#bot"); + }); + + it("escapes the message and the context values", () => { + const message = formatLogForTelegram(record({ msg: "hi", text: "a & b" })); + + expect(message).toContain("<b>hi</b>"); + expect(message).toContain("text: a & b"); + }); + + it("renders errors with a level tag", () => { + const message = formatLogForTelegram( + record({ level: levels.values.error, scope: "github", err: { stack: "Error: boom" }, tags: ["webhook"] }), + ); + + expect(message).toContain("
Error: boom
"); + expect(message).toContain("#webhook #github #error"); + }); + + it("uses a pre-rendered body instead of the generic layout", () => { + const message = formatLogForTelegram(record({ msg: "ignored", tg: "Custom:", deliveryId: "1" })); + + expect(message).toContain("Custom:"); + expect(message).not.toContain("ignored"); + expect(message).not.toContain("deliveryId"); + }); + + it("keeps messages within Telegram's limit", () => { + const message = formatLogForTelegram(record({ msg: "x".repeat(10_000) })); + + expect(message.length).toBeLessThanOrEqual(4096); + }); +}); diff --git a/src/lib/logger/format.ts b/src/lib/logger/format.ts new file mode 100644 index 0000000..0180f49 --- /dev/null +++ b/src/lib/logger/format.ts @@ -0,0 +1,87 @@ +import { levels } from "pino"; + +import { escapeHtml } from "../escape-html.ts"; + +/** Telegram caps messages at 4096 characters, leave room for the header. */ +const MAX_MESSAGE_LENGTH = 3800; +const MAX_DETAILS_LENGTH = 2500; + +/** Keys owned by pino or handled explicitly, never rendered as context lines. */ +const reservedKeys = new Set(["err", "hostname", "level", "msg", "name", "pid", "scope", "tags", "tg", "time"]); + +const levelIcons: Record = { + trace: "šŸ”¬", + debug: "šŸž", + info: "ā„¹ļø", + warn: "āš ļø", + error: "āŒ", + fatal: "šŸ’€", +}; + +export interface LogRecord { + level: number; + time: number; + msg?: string; + /** Logical area of the app, e.g. `bot` or `github`. */ + scope?: string; + /** Pre-rendered, already escaped HTML body used instead of the generic layout. */ + tg?: string; + /** Extra hashtags appended to the Telegram message. */ + tags?: string[]; + err?: { type?: string; message?: string; stack?: string }; + [key: string]: unknown; +} + +function truncate(text: string, max: number): string { + return text.length > max ? `${text.slice(0, max)}\nā€¦` : text; +} + +function stringifyValue(value: unknown): string { + if (typeof value === "string") return value; + if (typeof value === "number" || typeof value === "boolean") return String(value); + + try { + return JSON.stringify(value) ?? String(value); + } catch { + return String(value); + } +} + +function getTags(record: LogRecord, label: string): string { + const tags = new Set(record.tags ?? []); + if (record.scope) tags.add(record.scope); + if (label === "error" || label === "fatal" || label === "warn") tags.add(label); + + return [...tags].map((tag) => `#${tag.replace(/\W/g, "_")}`).join(" "); +} + +function getErrorDetails(err: NonNullable): string { + return err.stack ?? [err.type, err.message].filter(Boolean).join(": "); +} + +/** Renders a pino log record as the HTML message sent to the debug chat. */ +export function formatLogForTelegram(record: LogRecord): string { + const label = levels.labels[record.level] ?? "info"; + const scope = record.scope ? ` Ā· ${escapeHtml(record.scope)}` : ""; + const lines = [`${levelIcons[label] ?? "ā„¹ļø"} ${label.toUpperCase()}${scope}`]; + + if (record.tg) { + lines.push(record.tg); + } else { + if (record.msg) lines.push(escapeHtml(record.msg)); + + const context = Object.entries(record).filter(([key, value]) => !reservedKeys.has(key) && value != null); + if (context.length > 0) { + lines.push("", ...context.map(([key, value]) => `${key}: ${escapeHtml(stringifyValue(value))}`)); + } + + if (record.err) { + lines.push("", `
${escapeHtml(truncate(getErrorDetails(record.err), MAX_DETAILS_LENGTH))}
`); + } + } + + const tags = getTags(record, label); + if (tags) lines.push("", tags); + + return truncate(lines.join("\n"), MAX_MESSAGE_LENGTH); +} diff --git a/src/lib/logger/index.ts b/src/lib/logger/index.ts new file mode 100644 index 0000000..56f12cf --- /dev/null +++ b/src/lib/logger/index.ts @@ -0,0 +1,52 @@ +import type { StreamEntry } from "pino"; + +import { config } from "#config"; +import pino from "pino"; + +import { createTelegramStream } from "./telegram-stream.ts"; + +const logLevels = ["trace", "debug", "info", "warn", "error", "fatal", "silent"] as const; + +export type LogLevel = (typeof logLevels)[number]; + +function toLevel(value: string, fallback: LogLevel): LogLevel { + return logLevels.includes(value as LogLevel) ? (value as LogLevel) : fallback; +} + +function levelValue(level: LogLevel): number { + return level === "silent" ? Number.POSITIVE_INFINITY : pino.levels.values[level]; +} + +const outputLevel = toLevel(config.logger.level, "info"); +const telegramLevel = toLevel(config.logger.telegramLevel, "info"); + +const streams: StreamEntry[] = []; + +if (outputLevel !== "silent") { + streams.push( + { level: outputLevel, stream: pino.destination({ dest: 1, sync: true }) }, + { level: outputLevel, stream: pino.destination({ dest: config.logger.filePath, mkdir: true, sync: true }) }, + ); +} + +// Without a report chat there is nowhere to mirror records to. +if (telegramLevel !== "silent" && config.bot.reportChatId) { + streams.push({ level: telegramLevel, stream: createTelegramStream() }); +} + +/** The lowest level any destination asks for; anything below it is never emitted. */ +const rootLevel = streams + .map((stream) => stream.level as LogLevel) + .reduce((lowest, level) => (levelValue(level) < levelValue(lowest) ? level : lowest), "silent" as LogLevel); + +/** Application-wide logger, writing to stdout, the log file and the Telegram debug chat. */ +export const logger = pino({ level: rootLevel }, pino.multistream(streams)); + +/** Telegram bot activity: incoming updates, commands and their failures. */ +export const botLogger = logger.child({ scope: "bot" }); + +/** GitHub activity: received webhook deliveries and their failures. */ +export const githubLogger = logger.child({ scope: "github" }); + +/** HTTP layer: server lifecycle and rejected requests. */ +export const apiLogger = logger.child({ scope: "api" }); diff --git a/src/lib/logger/telegram-stream.ts b/src/lib/logger/telegram-stream.ts new file mode 100644 index 0000000..df83c0f --- /dev/null +++ b/src/lib/logger/telegram-stream.ts @@ -0,0 +1,57 @@ +import { autoRetry } from "@grammyjs/auto-retry"; +import { config } from "#config"; +import { Api } from "grammy"; + +import type { LogRecord } from "./format.ts"; + +import { sendReport } from "../telegram/report.ts"; +import { formatLogForTelegram } from "./format.ts"; + +/** Records are dropped once this many sends are in flight, so logging never becomes a memory leak. */ +const MAX_PENDING = 100; + +/** + * A pino destination that mirrors records into the Telegram debug chat. + * + * It talks to Telegram through its own {@link Api} instance rather than the bot, + * so that every module ā€” the bot included ā€” can depend on the logger. + * + * Sends are serialized to keep records in order and within Telegram's rate + * limits. Failures go to stderr instead of the logger, otherwise a failing chat + * would log itself in a loop. + */ +export function createTelegramStream() { + const api = new Api(config.bot.token); + api.config.use(autoRetry({ maxRetryAttempts: 2 })); + + let queue = Promise.resolve(); + let pending = 0; + + return { + write(line: string) { + if (pending >= MAX_PENDING) return; + + let record: LogRecord; + try { + record = JSON.parse(line) as LogRecord; + } catch { + return; + } + + pending += 1; + const message = formatLogForTelegram(record); + + queue = queue + .then(() => sendReport(api, message)) + .then( + () => undefined, + (error: unknown) => { + process.stderr.write(`failed to send log to telegram: ${String(error)}\n`); + }, + ) + .finally(() => { + pending -= 1; + }); + }, + }; +} diff --git a/src/lib/telegram/createCommand.ts b/src/lib/telegram/createCommand.ts index 2f4c166..37dd640 100644 --- a/src/lib/telegram/createCommand.ts +++ b/src/lib/telegram/createCommand.ts @@ -50,6 +50,7 @@ export const createCommand = >(args: CreateCom const command = parse(ctx.message.text); if (!command.success) { + ctx.logger.info({ command: name, text: ctx.message.text }, "command rejected"); const message = typeof args.helpMessage === "function" ? args.helpMessage(ctx.t) : args.helpMessage; return ctx.html.reply(message ?? `Invalid command usage. Correct format: /${template}`); } @@ -62,9 +63,16 @@ export const createCommand = >(args: CreateCom messageValidator, validator, async (ctx, next) => { - // @ts-expect-error It's safe - // eslint-disable-next-line @typescript-eslint/no-unsafe-return, @typescript-eslint/no-unsafe-call, @typescript-eslint/no-unsafe-member-access - return handler(ctx, next).catch(ctx.report); + const startedAt = performance.now(); + ctx.logger.info({ command: name, args: ctx.args }, "command received"); + + try { + // @ts-expect-error It's safe + await handler(ctx, next); + ctx.logger.debug({ command: name, durationMs: Math.round(performance.now() - startedAt) }, "command handled"); + } catch (error) { + ctx.report(error); + } }, ] satisfies Middleware>>[]; diff --git a/tsconfig.json b/tsconfig.json index 94bfd98..0753126 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -22,6 +22,7 @@ "#db": ["./src/db/index.ts"], "#bot": ["./src/bot/bot.ts"], "#github": ["./src/lib/github/index.ts"], + "#logger": ["./src/lib/logger/index.ts"], "#webhooks": ["./src/lib/github/webhooks/index.ts"], "#telegram": ["./src/lib/index.ts"] }