diff --git a/.env.example b/.env.example index 107634a..609a8a7 100644 --- a/.env.example +++ b/.env.example @@ -9,3 +9,4 @@ DEFAULT_BASE_BRANCH=main MAX_INLINE_COMMENTS=5 REVIEW_TIMEOUT_MS=120000 DEDUPE_TTL_SECONDS=1800 +LOG_LEVEL=info diff --git a/README.md b/README.md index 886aeee..901ffb7 100644 --- a/README.md +++ b/README.md @@ -156,6 +156,7 @@ Optional: - `MAX_INLINE_COMMENTS` (default: `5`) - `REVIEW_TIMEOUT_MS` (default: `120000`) - `DEDUPE_TTL_SECONDS` (default: `1800`) +- `LOG_LEVEL` (default: `info`; options: `debug`, `info`, `warn`, `error`) See `.env.example`. @@ -201,3 +202,4 @@ Post-validation rules: - Do not log tokens or raw auth headers. - Dedupe is in-memory (resets on restart). - Best deployment model is a central service with org-level webhook and per-repo opt-out config. +- Logs are structured JSON to simplify filtering in Docker/log collectors. diff --git a/src/logging/logger.ts b/src/logging/logger.ts new file mode 100644 index 0000000..c7e21f8 --- /dev/null +++ b/src/logging/logger.ts @@ -0,0 +1,41 @@ +type LogLevel = "debug" | "info" | "warn" | "error"; + +const levelOrder: Record = { + debug: 10, + info: 20, + warn: 30, + error: 40 +}; + +const currentLevel = resolveLevel(process.env.LOG_LEVEL); + +export function log(level: LogLevel, message: string, context: Record = {}): void { + if (levelOrder[level] < levelOrder[currentLevel]) { + return; + } + + const payload = { + timestamp: new Date().toISOString(), + level, + message, + ...context + }; + + const line = JSON.stringify(payload); + if (level === "error" || level === "warn") { + console.error(line); + return; + } + console.log(line); +} + +function resolveLevel(level: string | undefined): LogLevel { + if (!level) { + return "info"; + } + const normalized = level.toLowerCase(); + if (normalized === "debug" || normalized === "info" || normalized === "warn" || normalized === "error") { + return normalized; + } + return "info"; +} diff --git a/src/run/retry.ts b/src/run/retry.ts index d2c8344..4dbf2e9 100644 --- a/src/run/retry.ts +++ b/src/run/retry.ts @@ -1,8 +1,12 @@ +import { log } from "../logging/logger.js"; + export async function retry(input: { fn: () => Promise; retries: number; initialDelayMs: number; shouldRetry?: (error: unknown) => boolean; + operationName?: string; + correlationId?: string; }): Promise { let attempt = 0; let delay = input.initialDelayMs; @@ -15,6 +19,13 @@ export async function retry(input: { if (!retryable || attempt > input.retries) { throw error; } + log("warn", "Retrying operation after error", { + operation: input.operationName ?? "unknown", + attempt, + retries: input.retries, + correlation_id: input.correlationId, + error: error instanceof Error ? error.message : String(error) + }); await sleep(delay); delay *= 2; } diff --git a/src/run/review-runner.ts b/src/run/review-runner.ts index a80f10b..7d08155 100644 --- a/src/run/review-runner.ts +++ b/src/run/review-runner.ts @@ -8,6 +8,7 @@ import { deletePriorBotReviews, postReview } from "../gitea/review-api.js"; import { removeBotFromReviewers } from "../gitea/reviewer-api.js"; import { buildReviewPrompt } from "../prompt/build-review-prompt.js"; import { RoutedEvent } from "../types/events.js"; +import { log } from "../logging/logger.js"; import { retry } from "./retry.js"; export async function runReview(input: { @@ -28,6 +29,13 @@ export async function runReview(input: { headSha }); if (input.dedupe.has(dedupeKey)) { + log("info", "Review skipped: duplicate webhook", { + correlation_id: input.correlationId, + owner, + repo, + pr_number: prNumber, + head_sha: headSha + }); return "skipped"; } input.dedupe.mark(dedupeKey); @@ -36,7 +44,9 @@ export async function runReview(input: { const pull = await retry({ fn: () => gitea.getPull(owner, repo, prNumber), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "getPull", + correlationId: input.correlationId }); const { config: repoConfig, ruleFiles } = await retry({ fn: () => @@ -47,7 +57,9 @@ export async function runReview(input: { ref: pull.head.ref }), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "loadRepoConfig", + correlationId: input.correlationId }); const should = shouldProcessEvent({ @@ -57,13 +69,23 @@ export async function runReview(input: { botLogin: input.env.GITEA_BOT_LOGIN }); if (!should.process) { + log("info", "Review skipped by policy", { + correlation_id: input.correlationId, + owner, + repo, + pr_number: prNumber, + head_sha: headSha, + reason: should.reason ?? "unknown" + }); return "skipped"; } const files = await retry({ fn: () => gitea.getPullFiles(owner, repo, prNumber), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "getPullFiles", + correlationId: input.correlationId }); const maxInlineComments = repoConfig.max_inline_comments ?? input.env.MAX_INLINE_COMMENTS; const prompt = buildReviewPrompt({ @@ -83,7 +105,9 @@ export async function runReview(input: { model: repoConfig.model }), retries: 2, - initialDelayMs: 500 + initialDelayMs: 500, + operationName: "runCursorReview", + correlationId: input.correlationId }); await retry({ @@ -96,7 +120,9 @@ export async function runReview(input: { botLogin: input.env.GITEA_BOT_LOGIN }), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "deletePriorBotReviews", + correlationId: input.correlationId }); await retry({ @@ -111,7 +137,9 @@ export async function runReview(input: { maxInlineComments }), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "postReview", + correlationId: input.correlationId }); await retry({ @@ -124,18 +152,18 @@ export async function runReview(input: { botLogin: input.env.GITEA_BOT_LOGIN }), retries: 2, - initialDelayMs: 300 + initialDelayMs: 300, + operationName: "removeBotFromReviewers", + correlationId: input.correlationId }); - console.log( - JSON.stringify({ - correlation_id: input.correlationId, - owner, - repo, - pr_number: prNumber, - head_sha: headSha, - outcome: "success" - }) - ); + log("info", "Review completed", { + correlation_id: input.correlationId, + owner, + repo, + pr_number: prNumber, + head_sha: headSha, + outcome: "success" + }); return "success"; } diff --git a/src/server.ts b/src/server.ts index 13841f2..9f5aef5 100644 --- a/src/server.ts +++ b/src/server.ts @@ -2,6 +2,7 @@ import crypto from "node:crypto"; import http from "node:http"; import { loadEnv } from "./config/env.js"; import { DedupeStore } from "./domain/dedupe-store.js"; +import { log } from "./logging/logger.js"; import { runReview } from "./run/review-runner.js"; import { PullRequestWebhookPayload } from "./types/events.js"; import { routeEvent } from "./webhook/event-router.js"; @@ -24,9 +25,13 @@ const server = http.createServer(async (req, res) => { } const body = await readBody(req); + const correlationId = crypto.randomUUID(); const signature = req.headers["x-gitea-signature"]; const signatureValue = Array.isArray(signature) ? signature[0] : signature; if (!verifySignature({ secret: env.WEBHOOK_SECRET, body, signatureHeader: signatureValue })) { + log("warn", "Webhook rejected: invalid signature", { + correlation_id: correlationId + }); res.writeHead(401); res.end("invalid signature"); return; @@ -35,6 +40,15 @@ const server = http.createServer(async (req, res) => { const eventNameHeader = req.headers["x-gitea-event"]; const eventName = Array.isArray(eventNameHeader) ? eventNameHeader[0] : eventNameHeader; const payload = JSON.parse(body) as PullRequestWebhookPayload; + log("info", "Webhook received", { + correlation_id: correlationId, + event: eventName ?? "unknown", + action: payload.action, + owner: payload.repository.owner.login, + repo: payload.repository.name, + pr_number: payload.pull_request.number, + head_sha: payload.pull_request.head.sha + }); const routed = routeEvent({ eventName, payload, @@ -42,12 +56,16 @@ const server = http.createServer(async (req, res) => { }); if (!routed) { + log("info", "Webhook ignored by router", { + correlation_id: correlationId, + event: eventName ?? "unknown", + action: payload.action + }); res.writeHead(202); res.end("ignored"); return; } - const correlationId = crypto.randomUUID(); try { const outcome = await runReview({ env, @@ -58,20 +76,18 @@ const server = http.createServer(async (req, res) => { res.writeHead(200); res.end(outcome); } catch (error) { - console.error( - JSON.stringify({ - correlation_id: correlationId, - outcome: "failed", - error: error instanceof Error ? error.message : String(error) - }) - ); + log("error", "Webhook processing failed", { + correlation_id: correlationId, + outcome: "failed", + error: error instanceof Error ? error.message : String(error) + }); res.writeHead(500); res.end("failed"); } }); server.listen(env.PORT, () => { - console.log(`gitea-pr-review-bot listening on :${env.PORT}`); + log("info", "Service started", { port: env.PORT }); }); function readBody(req: http.IncomingMessage): Promise {