From 611cdd4458d676aaedfdcbbbfee35965031d4157 Mon Sep 17 00:00:00 2001 From: hltav Date: Wed, 7 Oct 2026 15:49:31 -0300 Subject: [PATCH] feat(PAV-126): adiciona observabilidade operacional completa --- .env.example | 3 + .gitignore | 2 + BACKEND.md | 43 ++ SCRAPER.md | 54 ++ backend/src/lib/cache.ts | 12 +- backend/src/metrics/metrics.ts | 20 + backend/src/middleware/metrics.ts | 30 +- .../observability/observability.controller.ts | 7 + .../observability/observability.service.ts | 27 + .../observability/observability.types.ts | 112 +++++ .../src/modules/jobs/cache/jobSearchCache.ts | 80 ++- backend/src/routes/admin.routes.ts | 6 + backend/src/swagger.ts | 45 ++ .../integration/routes/admin.routes.test.ts | 6 + backend/tests/unit/app.test.ts | 3 + backend/tests/unit/libs/cache.test.ts | 3 + .../tests/unit/metrics/operational.test.ts | 137 +++++ .../modules/admin/operationalSnapshot.test.ts | 181 +++++++ docker-compose.observability.yml | 3 +- docker-compose.yml | 1 + observability/prometheus/prometheus.yml | 9 + observability/prometheus/rules/alerts.yml | 83 +++ observability/prometheus/rules/recording.yml | 32 ++ observability/prometheus/rules/tests.yml | 51 ++ scraper-go/cmd/server/observability.go | 162 ++++++ scraper-go/cmd/server/observability_test.go | 107 ++++ scraper-go/cmd/server/server.go | 8 + scraper-go/go.mod | 1 + scraper-go/internal/catalog/store.go | 23 +- scraper-go/internal/catalogops/maintenance.go | 52 +- .../internal/catalogops/observability.go | 69 +++ .../internal/catalogops/observability_test.go | 59 +++ scraper-go/internal/classifier/classifier.go | 6 +- scraper-go/internal/config/config.go | 10 + scraper-go/internal/config/config_test.go | 24 + scraper-go/internal/cronjob/cronjob.go | 7 + scraper-go/internal/domain/job.go | 1 + scraper-go/internal/jobindex/index.go | 30 +- scraper-go/internal/jobindex/index_test.go | 25 + scraper-go/internal/jobstore/jobstore.go | 16 +- scraper-go/internal/metrics/classification.go | 48 ++ scraper-go/internal/metrics/maintenance.go | 115 +++++ scraper-go/internal/metrics/operational.go | 206 ++++++++ .../internal/metrics/operational_test.go | 195 +++++++ scraper-go/internal/metrics/state.go | 475 ++++++++++++++++++ scraper-go/internal/pipeline/budget.go | 7 + scraper-go/internal/pipeline/pipeline.go | 25 +- scraper-go/internal/pipeline/process.go | 36 ++ scraper-go/internal/pipeline/scrape.go | 2 +- scraper-go/internal/pipeline/search.go | 7 +- scraper-go/internal/runlock/runlock.go | 23 +- scraper-go/internal/runlock/runlock_test.go | 27 + 52 files changed, 2659 insertions(+), 57 deletions(-) create mode 100644 backend/tests/unit/metrics/operational.test.ts create mode 100644 backend/tests/unit/modules/admin/operationalSnapshot.test.ts create mode 100644 observability/prometheus/rules/alerts.yml create mode 100644 observability/prometheus/rules/recording.yml create mode 100644 observability/prometheus/rules/tests.yml create mode 100644 scraper-go/cmd/server/observability.go create mode 100644 scraper-go/cmd/server/observability_test.go create mode 100644 scraper-go/internal/catalogops/observability.go create mode 100644 scraper-go/internal/catalogops/observability_test.go create mode 100644 scraper-go/internal/metrics/classification.go create mode 100644 scraper-go/internal/metrics/maintenance.go create mode 100644 scraper-go/internal/metrics/operational.go create mode 100644 scraper-go/internal/metrics/operational_test.go create mode 100644 scraper-go/internal/metrics/state.go diff --git a/.env.example b/.env.example index dbde23b1..ba0fd7f3 100644 --- a/.env.example +++ b/.env.example @@ -161,3 +161,6 @@ LEVER_INCLUDE_ALL_JOBS=true SCRAPER_CATALOG_LIFETIME=216h # Cache de páginas de busca, limitado também pela próxima expiração de vaga. JOB_SEARCH_CACHE_TTL_SECONDS=120 + +# Versão da aplicação para status operacional (não é label Prometheus). +APPLICATION_VERSION=local diff --git a/.gitignore b/.gitignore index 98a2f316..09b714ab 100644 --- a/.gitignore +++ b/.gitignore @@ -17,6 +17,8 @@ npm-debug.log yarn-error.log yarn-debug.log PAV-124_REPORT.md +PAV-125_REPORT.md +PAV-126_REPORT.md # Test coverage reports coverage/ diff --git a/BACKEND.md b/BACKEND.md index 2bf18e62..0e8133d8 100644 --- a/BACKEND.md +++ b/BACKEND.md @@ -634,3 +634,46 @@ podem afetar uma resposta, embora uma geração modificada impeça publicar cach obsoleto. O índice usa expiração em segundos; existe granularidade inferior a um segundo em relação aos timestamps SQL. A meta operacional de p95 < 500 ms exige medição com volume e concorrência representativos; testes locais não a comprovam. + + +## Snapshot administrativo e métricas de busca — PAV-126 + +`GET /admin/observability` (também sob o prefixo API existente) exige sessão, +role administrativa e permissão `observability.metrics`. Usa o padrão de resposta +administrativa direto, `Cache-Control: no-store`, com contrato: + +```json +{ + "status": "partial", + "timestamp": "2026-10-07T00:00:00.000Z", + "processor": null, + "availability": { "scraper": "down" } +} +``` + +Quando o Processor responde, `processor` contém execution, lock, concurrency, +progress, queues, resources, errors, rejectedTitles/rejectedTitlesSince, +dependencies e index. Sem histórico, execution.status é idle, os timestamps/source/ +stage são null e durationSeconds é zero. Falhas de PostgreSQL/Valkey preservam o +snapshot e retornam status partial. O backend faz uma única chamada interna com +prazo de 2.5s, valida com Zod e remove campos extras antes de responder. Ausência +ou resposta inválida do Processor resulta no formato parcial acima, HTTP 200. +Prometheus não é dependência dessa rota. As rotas administrativas anteriores, +auth, rate limiting e contratos de famílias permanecem preservados. + +Métricas HTTP existentes `http_request_duration_seconds`/`http_requests_total` +continuam com os mesmos nomes/labels. Route usa templates Express; caminhos sem +match caem em `__unmatched__`, salvo rotas prioritárias estáticas conhecidas. +Query strings e IDs não viram labels. Methods desconhecidos caem em OTHER. +Os buckets existentes permitem estimar p50/p95/p99, sem promessa de desempenho. + +O cache PAV-125 expõe `candidate_jobs_search_cache_requests_total` com hit/miss/ +stale/error, histogram de get/set/invalidate e invalidações por motivo fixo. +Cada request tem um resultado: reutilização local via singleflight conta como hit; +cache indisponível conta error; publicação recusada por geração diferente conta +stale. As keys, fingerprints, TTL, CAS e ranking não mudaram. Go observa invalidações +de catálogo/rebuild; Node observa a invalidação manual já existente. Nada registra +keys, texto livre, localização privada ou dados de usuário em labels. + +Ver `observability/PAV-126_REPORT.md` para inventário, regras, testes, limitações e +rollback. A meta de busca p95 < 500ms requer validação em staging representativo. diff --git a/SCRAPER.md b/SCRAPER.md index fcb61d9b..56a281b5 100644 --- a/SCRAPER.md +++ b/SCRAPER.md @@ -582,3 +582,57 @@ forward-only: não existe down migration destrutiva automática. Não remover a para reverter código; preservar os dados e planejar eventual arquivamento separado. Nenhuma operação usa FLUSH ou o comando KEYS; cleanup só alcança o manifesto do namespace selecionado e recusa a versão ativa e chaves externas. + + +## Observabilidade operacional — PAV-126 + +O `/metrics` mantém as métricas `scraper_*`, `go_*` e `process_*` existentes. +As métricas `candidate_scraper_*` acrescentam resultados por origem, lock, +concorrência, progresso, discovery mode, classificação, persistência e projeção. +`other` é exclusivamente diagnóstico; a taxonomia pública continua com 13 famílias. +Providers são os oito IDs de `ports` ou `unknown`. IDs de execução/vaga, títulos, +keywords, empresas, tokens e mensagens livres nunca são labels. + +O estado operacional é atualizado nos pontos reais do pipeline e protegido por +mutex. As quatro filas refletem canais e buffers reais. Ao terminar, active, +waiting e depths voltam a zero. `keywordsTotal/Processed` contam entradas consumidas +pelas tarefas, incluindo fan-out; não contam keywords únicas. Totais de batches não +são inventados quando desconhecidos. ProvidersCompleted/AdaptersProcessed indicam +conclusão de tarefas, inclusive com erro; a situação aparece nas métricas de resultado. +O comportamento anterior de sucesso parcial de coleta permanece preservado. + +A ordem continua classificação → commit PostgreSQL → projeção Valkey. Contadores +de persistência/indexação medem tentativas, inclusive retries; não são contagens de +vagas únicas no catálogo. Falhas e rollbacks possuem categorias fixas. Invalidações +são observadas somente após publicação bem-sucedida da geração. A telemetria não +transforma uma publicação válida em falha se seu hash estiver corrompido. + +Manutenções CLI explícitas gravam contadores/histogramas de operação e um resumo +com TTL de 24h. O servidor amostra o hash fixo a cada 15s, com prazo de 2s, e conserva +os últimos contadores conhecidos se Valkey cair. `maintenance_telemetry_available` +e o timestamp da amostra permitem identificar defasagem. O scrape Prometheus não +faz I/O externo. A versão ativa está no snapshot administrativo, sem label dinâmica. +Não há rebuild nem reconciliação automática nova. + +O GET interno `/admin/observability` é técnico e deve permanecer na rede privada +existente do Processor. Autenticação/autorização continuam no backend. O snapshot +inclui estado, última execução, próxima execução, lock/TTL, concorrência, progresso, +filas, recursos, erros, versões e última manutenção. PostgreSQL/Valkey são sondados +em paralelo com prazo compartilhado de 2s e um pool Redis de diagnóstico separado; +não há consulta ao catálogo nem ao Prometheus. Campos disponíveis permanecem na +resposta quando uma dependência falha. Configure `APPLICATION_VERSION` no deploy; +o default é `unknown` (`local` no exemplo de ambiente). + +Os títulos rejeitados são um agregado administrativo em memória, normalizado, +limitado a 100 pares título/motivo e top 10 retornados. Reinicia por execução ou +após 24h; pode omitir novos títulos ao atingir o limite. Não é histórico completo. +Títulos com email/URL são descartados; não há vaga/descrição completa nem labels +por título. CPU percentual é derivada entre leituras do snapshot, inicialmente +null; RSS depende de `/proc`. CPU/container limits/GC continuam nos collectors +Go/process/cAdvisor existentes, incluindo GOMAXPROCS e GOMEMLIMIT. + +Recording rules e alertas ficam em `observability/prometheus/rules`. Alertas de +CPU/memória usam janelas sustentadas e os limites atuais de 1.5 CPU/2GiB; revisar +limiares se recursos mudarem. Prometheus envia ao Alertmanager existente, cujo +receiver de exemplo não entrega notificações: configurar o destino operacional. +A validação e o inventário completo estão em `observability/PAV-126_REPORT.md`. diff --git a/backend/src/lib/cache.ts b/backend/src/lib/cache.ts index d4fc6bc6..a6999a05 100644 --- a/backend/src/lib/cache.ts +++ b/backend/src/lib/cache.ts @@ -1,3 +1,7 @@ +import { + searchCacheDuration, + searchCacheInvalidations, +} from "../metrics/metrics"; import { normalizeJobTaxonomy } from "../modules/jobs/types/professionalTaxonomy"; import { randomUUID } from "node:crypto"; import { createClient, type RedisClientType } from "redis"; @@ -488,7 +492,13 @@ export async function cacheClearJobs(): Promise<{ if (await client.get("scraper:jobs:index-version")) { // Catalog projections are owned by the Processor. Clearing HTTP search // cache must not delete an active validated namespace or durable jobs. - await client.incr("jobs:search:generation"); + const end = searchCacheDuration.startTimer({ operation: "invalidate" }); + try { + await client.incr("jobs:search:generation"); + searchCacheInvalidations.inc({ reason: "manual" }); + } finally { + end(); + } return { deleted: 0, patterns: ["jobs:search:generation"] }; } const patterns = ["scraper:job:*", "scraper:jobs:*"]; diff --git a/backend/src/metrics/metrics.ts b/backend/src/metrics/metrics.ts index b66935f9..b45c5e00 100644 --- a/backend/src/metrics/metrics.ts +++ b/backend/src/metrics/metrics.ts @@ -37,3 +37,23 @@ export const cacheOperationsTotal = new client.Counter({ labelNames: ["operation", "result"], registers: [register], }); + +export const searchCacheRequests = new client.Counter({ + name: "candidate_jobs_search_cache_requests_total", + help: "Search cache outcomes", + labelNames: ["result"], + registers: [register], +}); +export const searchCacheDuration = new client.Histogram({ + name: "candidate_jobs_search_cache_operation_duration_seconds", + help: "Search cache operation duration", + labelNames: ["operation"], + buckets: [0.001, 0.005, 0.01, 0.05, 0.1, 0.5, 1, 5], + registers: [register], +}); +export const searchCacheInvalidations = new client.Counter({ + name: "candidate_jobs_search_cache_invalidations_total", + help: "Successful search cache generation invalidations", + labelNames: ["reason"], + registers: [register], +}); diff --git a/backend/src/middleware/metrics.ts b/backend/src/middleware/metrics.ts index 789a6ddd..8fa74eb1 100644 --- a/backend/src/middleware/metrics.ts +++ b/backend/src/middleware/metrics.ts @@ -1,6 +1,17 @@ import type { NextFunction, Request, Response } from "express"; import { httpRequestDuration, httpRequestsTotal } from "../metrics/metrics"; +const priorityRoutes = new Set( + [ + "/jobs/search", + "/health", + "/auth/login", + "/admin/scrapers", + "/admin/observability", + "/metrics", + ].flatMap((route) => [route, `/api/v1${route}`]), +); + export function metricsMiddleware( req: Request, res: Response, @@ -9,13 +20,26 @@ export function metricsMiddleware( const end = httpRequestDuration.startTimer(); res.on("finish", () => { - // route já resolvido pelo Express (com :params), com fallback pro path cru + // Express templates only. Unmatched/auth-short-circuited requests must not + // expose arbitrary paths, query strings or dynamic IDs. const route = req.route?.path ? `${req.baseUrl}${req.route.path}` - : req.path; + : priorityRoutes.has(req.path) + ? req.path + : "__unmatched__"; const labels = { - method: req.method, + method: [ + "GET", + "POST", + "PUT", + "PATCH", + "DELETE", + "HEAD", + "OPTIONS", + ].includes(req.method) + ? req.method + : "OTHER", route, status_code: String(res.statusCode), }; diff --git a/backend/src/modules/admin/observability/observability.controller.ts b/backend/src/modules/admin/observability/observability.controller.ts index 53831568..8205e7f3 100644 --- a/backend/src/modules/admin/observability/observability.controller.ts +++ b/backend/src/modules/admin/observability/observability.controller.ts @@ -13,6 +13,13 @@ export class ObservabilityController { private readonly auditService: AuditService, ) {} + async getOperationalSnapshot(req: Request, res: Response) { + const result = await this.service.getOperationalSnapshot(); + this.auditService.fromRequest(req, "observability.metrics"); + res.set("Cache-Control", "no-store"); + return res.json(result); + } + async getHealth(req: Request, res: Response) { try { const result = await this.service.getHealth(); diff --git a/backend/src/modules/admin/observability/observability.service.ts b/backend/src/modules/admin/observability/observability.service.ts index 3b89b04a..772e9f78 100644 --- a/backend/src/modules/admin/observability/observability.service.ts +++ b/backend/src/modules/admin/observability/observability.service.ts @@ -1,3 +1,5 @@ +import { config } from "../../../config"; +import { ProcessorSnapshotSchema } from "./observability.types"; import { HealthService } from "./health.service"; import { MetricsService } from "./metrics.service"; import type { @@ -13,6 +15,31 @@ export class ObservabilityService { private readonly metricsService: MetricsService, ) {} + async getOperationalSnapshot() { + const timestamp = new Date().toISOString(); + try { + const response = await fetch(`${config.scraperUrl}/admin/observability`, { + signal: AbortSignal.timeout(2500), + }); + if (!response.ok) throw new Error("processor unavailable"); + const processor = ProcessorSnapshotSchema.parse(await response.json()); + return { + status: processor.status, + timestamp, + processor, + availability: { scraper: "ok" as const }, + }; + } catch { + // Dependency failure is distinct from an available Processor with no runs. + return { + status: "partial" as const, + timestamp, + processor: null, + availability: { scraper: "down" as const }, + }; + } + } + async getHealth(): Promise { return this.healthService.getHealthcheck(); } diff --git a/backend/src/modules/admin/observability/observability.types.ts b/backend/src/modules/admin/observability/observability.types.ts index c9e18e1c..c2e7a634 100644 --- a/backend/src/modules/admin/observability/observability.types.ts +++ b/backend/src/modules/admin/observability/observability.types.ts @@ -84,3 +84,115 @@ export const ObservabilityOverviewSchema = z.object({ metrics: MetricSnapshotSchema, }); export type ObservabilityOverview = z.infer; + +// Processor-owned runtime state. Unknown fields are stripped before forwarding, +// so an internal response cannot expose credentials or incidental payloads. +const nullableTimestamp = z.string().datetime().nullable(); +export const ProcessorSnapshotSchema = z.object({ + status: z.enum(["ok", "partial"]), + timestamp: z.string().datetime(), + execution: z.object({ + status: z.enum(["idle", "running", "canceling", "failed", "completed"]), + source: z.enum(["manual", "cron"]).nullable(), + startedAt: nullableTimestamp, + durationSeconds: z.number().nonnegative(), + finishedAt: nullableTimestamp, + lastDurationSeconds: z.number().nonnegative(), + lastStatus: z + .enum(["success", "failed", "canceled", "skipped", "timeout"]) + .nullable(), + nextRunAt: nullableTimestamp, + stage: z + .enum(["collection", "classification", "persistence", "indexing"]) + .nullable(), + applicationVersion: z.string().max(128), + taxonomyVersion: z.string().max(128), + }), + lock: z.object({ held: z.boolean(), ttlSeconds: z.number().nonnegative() }), + concurrency: z.object({ + configured: z.number().int().nonnegative(), + effective: z.number().int().nonnegative(), + active: z.number().int().nonnegative(), + waiting: z.number().int().nonnegative(), + }), + progress: z.object( + Object.fromEntries( + [ + "providersTotal", + "providersCompleted", + "adaptersTotal", + "adaptersProcessed", + "tasksTotal", + "tasksCompleted", + "tasksCanceled", + "keywordsTotal", + "keywordsProcessed", + "batchesCompleted", + ].map((k) => [k, z.number().int().nonnegative()]), + ), + ), + queues: z.object( + Object.fromEntries( + ["collection", "classification", "persistence", "indexing"].map((k) => [ + k, + z.object({ + depth: z.number().int().nonnegative(), + capacity: z.number().int().nonnegative(), + }), + ]), + ), + ), + resources: z.object({ + cpuSeconds: z.number().nonnegative(), + cpuPercent: z.number().nonnegative().nullable(), + memoryBytes: z.number().nonnegative().nullable(), + heapBytes: z.number().nonnegative(), + goroutines: z.number().int().nonnegative(), + gomaxprocs: z.number().int().positive(), + gomemlimitBytes: z.number().nonnegative(), + }), + errors: z.object({ + total: z.number().int().nonnegative(), + timeouts: z.number().int().nonnegative(), + }), + rejectedTitles: z + .array( + z.object({ + title: z.string().max(100), + count: z.number().int().nonnegative(), + reasonCode: z.enum([ + "negative_title", + "no_family_recognized", + "insufficient_title_evidence", + ]), + }), + ) + .max(10), + rejectedTitlesSince: z.string().datetime(), + dependencies: z.object({ + postgres: z.object({ status: z.enum(["ok", "down"]) }), + valkey: z.object({ status: z.enum(["ok", "degraded", "down"]) }), + }), + index: z.object({ + activeVersion: z.string().max(128), + rebuildProgress: z.number().int().nonnegative().nullable(), + maintenance: z + .object({ + operation: z.enum([ + "rebuild", + "reconcile", + "backfill", + "reclassify", + "expire", + "rollback", + ]), + status: z.enum(["success", "failed", "canceled"]), + durationSeconds: z.number().nonnegative(), + finishedAt: z.string().datetime(), + processed: z.number().int().nonnegative(), + divergences: z.number().int().nonnegative(), + }) + .nullable(), + }), +}); +export type ProcessorSnapshot = z.infer; diff --git a/backend/src/modules/jobs/cache/jobSearchCache.ts b/backend/src/modules/jobs/cache/jobSearchCache.ts index 6b8a5022..fe89e789 100644 --- a/backend/src/modules/jobs/cache/jobSearchCache.ts +++ b/backend/src/modules/jobs/cache/jobSearchCache.ts @@ -1,3 +1,7 @@ +import { + searchCacheRequests, + searchCacheDuration, +} from "../../../metrics/metrics"; import { jobSearchCacheKey } from "./jobSearchFingerprint"; import type { PaginationParams } from "../../../lib/pagination"; import type { ParsedJobSearchQuery } from "../types/jobSearch.types"; @@ -41,12 +45,21 @@ export class JobSearchCache { ): Promise { let generation: string | null; try { - generation = await this.store.generation(); + const end = searchCacheDuration.startTimer({ operation: "get" }); + try { + generation = await this.store.generation(); + } finally { + end(); + } } catch { + searchCacheRequests.inc({ result: "error" }); return query(); } // null means indexes are unavailable or being rebuilt; do not cache. - if (generation === null) return query(); + if (generation === null) { + searchCacheRequests.inc({ result: "stale" }); + return query(); + } const key = jobSearchCacheKey( filters, pagination, @@ -54,28 +67,55 @@ export class JobSearchCache { rankingContext, ); const existing = this.inFlight.get(key); - if (existing) return structuredClone(await existing); + if (existing) { + searchCacheRequests.inc({ result: "hit" }); + return structuredClone(await existing); + } const pending = (async () => { + let outcome: "hit" | "miss" | "stale" | "error" = "miss"; try { - const cached = await this.store.read(key); - if (cached && (await this.store.generation()) === generation) - return cached; - } catch { - // A cache outage must not hide a successful persistence query. - } - const page = await query(); - try { - await this.store.writeIfGeneration( - key, - page, - generation, - this.ttlSeconds, - ); - } catch { - // The query remains useful; the next request can repopulate the cache. + try { + const end = searchCacheDuration.startTimer({ operation: "get" }); + let cached; + let current; + try { + cached = await this.store.read(key); + current = await this.store.generation(); + } finally { + end(); + } + if (cached && current === generation) { + outcome = "hit"; + return cached; + } + outcome = cached ? "stale" : "miss"; + } catch { + outcome = "error"; + // A cache outage must not hide a successful persistence query. + } + const page = await query(); + try { + const end = searchCacheDuration.startTimer({ operation: "set" }); + try { + const published = await this.store.writeIfGeneration( + key, + page, + generation, + this.ttlSeconds, + ); + if (!published && outcome !== "error") outcome = "stale"; + } finally { + end(); + } + } catch { + outcome = "error"; + // The query remains useful; the next request can repopulate the cache. + } + return page; + } finally { + searchCacheRequests.inc({ result: outcome }); } - return page; })(); this.inFlight.set(key, pending); try { diff --git a/backend/src/routes/admin.routes.ts b/backend/src/routes/admin.routes.ts index 8b200655..8fe002d4 100644 --- a/backend/src/routes/admin.routes.ts +++ b/backend/src/routes/admin.routes.ts @@ -53,6 +53,12 @@ router.post( scrapersCtrl.triggerOne.bind(scrapersCtrl), ); +router.get( + "/observability", + requirePermission("observability", "metrics"), + observabilityCtrl.getOperationalSnapshot.bind(observabilityCtrl), +); + router.get( "/observability/metrics", requirePermission("observability", "metrics"), diff --git a/backend/src/swagger.ts b/backend/src/swagger.ts index cde64dc4..1eb21ec3 100644 --- a/backend/src/swagger.ts +++ b/backend/src/swagger.ts @@ -1,5 +1,7 @@ import path from "path"; import swaggerJsdoc from "swagger-jsdoc"; +import { z } from "zod"; +import { ProcessorSnapshotSchema } from "./modules/admin/observability/observability.types"; import { jobFilterOptions } from "./modules/jobs/controllers/jobFilterOptions.controller"; import { professionalFamilies } from "./modules/jobs/types/professionalTaxonomy"; @@ -1200,6 +1202,49 @@ const options: swaggerJsdoc.Options = { }, }, }, + "/admin/observability": { + get: { + tags: ["Admin"], + summary: "Estado operacional leve do Jobs Processor", + description: + "Exige admin e permissão observability.metrics. Responde 200 com status ok ou partial; processor null significa indisponível, execution.status idle significa disponível sem execução. Uma chamada interna limitada a 2.5s; não consulta Prometheus nem varre vagas. Recursos, lock, progresso, versões, resumo de manutenção e top 10 rejeições limitadas estão em processor. Sem histórico, timestamps/source/stage são null.", + security: [{ cookieAuth: [] }], + responses: { + "200": { + description: "Snapshot disponível ou parcial", + content: { + "application/json": { + schema: { + type: "object", + required: [ + "status", + "timestamp", + "processor", + "availability", + ], + properties: { + status: { type: "string", enum: ["ok", "partial"] }, + timestamp: { type: "string", format: "date-time" }, + processor: z.toJSONSchema( + ProcessorSnapshotSchema.nullable(), + { target: "openapi-3.0" }, + ), + availability: { + type: "object", + properties: { + scraper: { type: "string", enum: ["ok", "down"] }, + }, + }, + }, + }, + }, + }, + }, + "401": { description: "Não autenticado" }, + "403": { description: "Sem permissão administrativa" }, + }, + }, + }, "/admin/observability/health": { get: { tags: ["Admin"], diff --git a/backend/tests/integration/routes/admin.routes.test.ts b/backend/tests/integration/routes/admin.routes.test.ts index 8e527b37..bbbaa8cd 100644 --- a/backend/tests/integration/routes/admin.routes.test.ts +++ b/backend/tests/integration/routes/admin.routes.test.ts @@ -72,6 +72,9 @@ vi.mock("../../../src/routes/admin.context", () => ({ triggerOne: mocks.scrapersTriggerOne, }, observabilityCtrl: { + getOperationalSnapshot: vi.fn((_req, res) => + res.json({ status: "ok", processor: null }), + ), getHealth: mocks.health, getMetrics: mocks.metrics, getDashboards: mocks.dashboards, @@ -146,6 +149,7 @@ describe("Integration - Admin Routes", () => { await request(app).get("/admin/users").expect(403); await request(app).patch("/admin/users/user-2/block").expect(403); await request(app).get("/admin/observability/metrics").expect(403); + await request(app).get("/admin/observability").expect(403); expect(mocks.usersList).not.toHaveBeenCalled(); expect(mocks.blockUser).not.toHaveBeenCalled(); @@ -160,6 +164,7 @@ describe("Integration - Admin Routes", () => { await request(app).post("/admin/scrapers/run").expect(202); await request(app).post("/admin/scrapers/go-scraper/run").expect(202); await request(app).get("/admin/observability/metrics").expect(200); + await request(app).get("/api/v1/admin/observability").expect(200); await request(app).get("/admin/audit").expect(200); await request(app).get("/admin/users").expect(200); @@ -224,5 +229,6 @@ describe("Integration - Admin Routes", () => { } as any); await request(app).get("/admin/dashboard").expect(401); + await request(app).get("/admin/observability").expect(401); }); }); diff --git a/backend/tests/unit/app.test.ts b/backend/tests/unit/app.test.ts index bb4a7546..1b448975 100644 --- a/backend/tests/unit/app.test.ts +++ b/backend/tests/unit/app.test.ts @@ -70,6 +70,9 @@ vi.mock("../../src/logger.js", () => ({ })); vi.mock("../../src/metrics/metrics.js", () => ({ + searchCacheRequests: { inc: vi.fn() }, + searchCacheDuration: { startTimer: vi.fn(() => vi.fn()) }, + searchCacheInvalidations: { inc: vi.fn() }, register: { contentType: "text/plain", metrics: vi.fn().mockResolvedValue("") }, httpRequestDuration: { startTimer: vi.fn(() => vi.fn()) }, httpRequestsTotal: { inc: vi.fn() }, diff --git a/backend/tests/unit/libs/cache.test.ts b/backend/tests/unit/libs/cache.test.ts index b7604645..939e1b4c 100644 --- a/backend/tests/unit/libs/cache.test.ts +++ b/backend/tests/unit/libs/cache.test.ts @@ -32,6 +32,9 @@ const metricMocks = vi.hoisted(() => ({ })); vi.mock("../../../src/metrics/metrics", () => ({ + searchCacheRequests: { inc: vi.fn() }, + searchCacheDuration: { startTimer: vi.fn(() => vi.fn()) }, + searchCacheInvalidations: { inc: vi.fn() }, cacheOperationsTotal: { inc: metricMocks.cacheInc, }, diff --git a/backend/tests/unit/metrics/operational.test.ts b/backend/tests/unit/metrics/operational.test.ts new file mode 100644 index 00000000..bd399530 --- /dev/null +++ b/backend/tests/unit/metrics/operational.test.ts @@ -0,0 +1,137 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; +import express from "express"; +import request from "supertest"; +import { metricsMiddleware } from "../../../src/middleware/metrics"; +import { + register, + httpRequestsTotal, + searchCacheRequests, + searchCacheDuration, + searchCacheInvalidations, +} from "../../../src/metrics/metrics"; +import { JobSearchCache } from "../../../src/modules/jobs/cache/jobSearchCache"; +import { parseJobSearchQuery } from "../../../src/modules/jobs/parsers/jobSearchQuery.parser"; + +beforeEach(() => { + httpRequestsTotal.reset(); + searchCacheRequests.reset(); + searchCacheDuration.reset(); + searchCacheInvalidations.reset(); +}); +describe("operational metrics cardinality and cache", () => { + it("uses route templates and bounded unmatched/method labels", async () => { + const app = express(); + app.use(metricsMiddleware); + app.get("/users/:id", (_req, res) => res.json({ ok: true })); + await request(app).get("/users/private-user-id?email=secret@example.com"); + await request(app).get("/arbitrary-secret-job-id?token=private"); + const values = (await httpRequestsTotal.get()).values; + expect(values.map((v) => v.labels.route)).toEqual([ + "/users/:id", + "__unmatched__", + ]); + const serialized = JSON.stringify(values); + expect(serialized).not.toContain("private"); + expect(serialized).not.toContain("secret"); + }); + it.each(["hit", "miss", "stale", "error"])( + "records %s and get/set timing without key labels", + async (result) => { + const storage = { + generation: vi.fn().mockResolvedValue("v1"), + read: vi + .fn() + .mockResolvedValue(result === "hit" ? { jobs: [], total: 0 } : null), + writeIfGeneration: vi.fn().mockResolvedValue(true), + }; + if (result === "stale") storage.generation.mockResolvedValue(null); + if (result === "error") + storage.generation.mockRejectedValue(new Error("secret free error")); + await new JobSearchCache(storage).search( + parseJobSearchQuery({ + family: "product", + keywords: "private free text", + }), + { page: 1, limit: 20 }, + null, + async () => ({ jobs: [], total: 0 }), + ); + expect((await searchCacheRequests.get()).values).toContainEqual( + expect.objectContaining({ labels: { result }, value: 1 }), + ); + expect((await searchCacheDuration.get()).values).toContainEqual( + expect.objectContaining({ + metricName: + "candidate_jobs_search_cache_operation_duration_seconds_count", + labels: { operation: "get" }, + value: expect.any(Number), + }), + ); + }, + ); + it("rejects prohibited labels in the metrics registry", async () => { + for (const metric of await register.getMetricsAsJSON()) { + if ( + !metric.name.startsWith("candidate_") && + !metric.name.startsWith("http_") + ) + continue; + for (const value of metric.values) { + for (const label of Object.keys(value.labels)) { + expect([ + "result", + "operation", + "reason", + "route", + "method", + "status_code", + "le", + ]).toContain(label); + } + } + } + }); +}); + +it("counts a request once when a miss is followed by a cache write failure", async () => { + const storage = { + generation: vi.fn().mockResolvedValue("v1"), + read: vi.fn().mockResolvedValue(null), + writeIfGeneration: vi.fn().mockRejectedValue(new Error("write failed")), + }; + await new JobSearchCache(storage).search( + parseJobSearchQuery({ family: "product" }), + { page: 1, limit: 20 }, + null, + async () => ({ jobs: [], total: 0 }), + ); + const values = (await searchCacheRequests.get()).values; + expect(values).toEqual([ + expect.objectContaining({ labels: { result: "error" }, value: 1 }), + ]); + expect((await searchCacheDuration.get()).values).toContainEqual( + expect.objectContaining({ + labels: { operation: "set" }, + metricName: + "candidate_jobs_search_cache_operation_duration_seconds_count", + value: 1, + }), + ); +}); + +it("records a rejected generation publication as stale", async () => { + const storage = { + generation: vi.fn().mockResolvedValue("v1"), + read: vi.fn().mockResolvedValue(null), + writeIfGeneration: vi.fn().mockResolvedValue(false), + }; + await new JobSearchCache(storage).search( + parseJobSearchQuery({ family: "product" }), + { page: 1, limit: 20 }, + null, + async () => ({ jobs: [], total: 0 }), + ); + expect((await searchCacheRequests.get()).values).toEqual([ + expect.objectContaining({ labels: { result: "stale" }, value: 1 }), + ]); +}); diff --git a/backend/tests/unit/modules/admin/operationalSnapshot.test.ts b/backend/tests/unit/modules/admin/operationalSnapshot.test.ts new file mode 100644 index 00000000..79c68582 --- /dev/null +++ b/backend/tests/unit/modules/admin/operationalSnapshot.test.ts @@ -0,0 +1,181 @@ +import { beforeEach, describe, expect, it, vi } from "vitest"; +import { ObservabilityService } from "../../../../src/modules/admin/observability/observability.service"; +import { ProcessorSnapshotSchema } from "../../../../src/modules/admin/observability/observability.types"; +vi.mock("../../../../src/modules/admin/observability/health.service", () => ({ + HealthService: class {}, +})); +vi.mock("../../../../src/modules/admin/observability/metrics.service", () => ({ + MetricsService: class {}, +})); +const now = "2026-10-07T00:00:00.000Z"; +const fixture = { + status: "ok", + timestamp: now, + execution: { + status: "idle", + source: null, + startedAt: null, + durationSeconds: 0, + finishedAt: null, + lastDurationSeconds: 0, + lastStatus: null, + nextRunAt: null, + stage: null, + applicationVersion: "test", + taxonomyVersion: "v1", + }, + lock: { held: false, ttlSeconds: 0 }, + concurrency: { configured: 12, effective: 0, active: 0, waiting: 0 }, + progress: Object.fromEntries( + [ + "providersTotal", + "providersCompleted", + "adaptersTotal", + "adaptersProcessed", + "tasksTotal", + "tasksCompleted", + "tasksCanceled", + "keywordsTotal", + "keywordsProcessed", + "batchesCompleted", + ].map((k) => [k, 0]), + ), + queues: Object.fromEntries( + ["collection", "classification", "persistence", "indexing"].map((k) => [ + k, + { depth: 0, capacity: 0 }, + ]), + ), + resources: { + cpuSeconds: 0, + cpuPercent: null, + memoryBytes: null, + heapBytes: 0, + goroutines: 1, + gomaxprocs: 2, + gomemlimitBytes: 1500, + }, + errors: { total: 0, timeouts: 0 }, + rejectedTitles: [], + rejectedTitlesSince: now, + dependencies: { postgres: { status: "ok" }, valkey: { status: "ok" } }, + index: { + activeVersion: "bootstrap", + rebuildProgress: null, + maintenance: null, + }, +}; +describe("operational snapshot partial availability", () => { + beforeEach(() => vi.unstubAllGlobals()); + it("returns idle without history and makes only one bounded call", async () => { + const fetch = vi + .fn() + .mockResolvedValue({ ok: true, json: async () => fixture }); + vi.stubGlobal("fetch", fetch); + const result = await new ObservabilityService( + {} as any, + {} as any, + ).getOperationalSnapshot(); + expect(result.status).toBe("ok"); + expect(result.processor?.execution.status).toBe("idle"); + expect(fetch).toHaveBeenCalledOnce(); + expect(fetch.mock.calls[0][1].signal).toBeInstanceOf(AbortSignal); + }); + it("preserves partial running state and strips secrets", async () => { + vi.stubGlobal( + "fetch", + vi.fn().mockResolvedValue({ + ok: true, + json: async () => ({ + ...fixture, + status: "partial", + token: "secret", + execution: { + ...fixture.execution, + status: "running", + source: "cron", + startedAt: now, + stage: "classification", + }, + dependencies: { + postgres: { status: "down", error: "password secret" }, + valkey: { status: "ok" }, + }, + }), + }), + ); + const result = await new ObservabilityService( + {} as any, + {} as any, + ).getOperationalSnapshot(); + expect(result.status).toBe("partial"); + expect(result.processor?.execution.status).toBe("running"); + expect(JSON.stringify(result)).not.toContain("secret"); + }); + it.each(["timeout", "unavailable", "invalid"])( + "returns partial for %s", + async (kind) => { + const fetch = vi.fn(); + if (kind === "invalid") + fetch.mockResolvedValue({ + ok: true, + json: async () => ({ token: "secret" }), + }); + else fetch.mockRejectedValue(new Error(kind)); + vi.stubGlobal("fetch", fetch); + expect( + await new ObservabilityService( + {} as any, + {} as any, + ).getOperationalSnapshot(), + ).toMatchObject({ + status: "partial", + processor: null, + availability: { scraper: "down" }, + }); + }, + ); + it("validates the last execution, progress, resources and lock contract", () => { + const result = ProcessorSnapshotSchema.parse({ + ...fixture, + execution: { + ...fixture.execution, + status: "completed", + lastStatus: "success", + finishedAt: now, + lastDurationSeconds: 12, + }, + lock: { held: true, ttlSeconds: 90 }, + }); + expect(result.execution.lastStatus).toBe("success"); + expect(result.lock.held).toBe(true); + expect(result.progress.tasksTotal).toBe(0); + }); +}); + +it("honors the internal deadline signal and returns partial after abort", async () => { + const controller = new AbortController(); + const timeout = vi + .spyOn(AbortSignal, "timeout") + .mockReturnValue(controller.signal); + vi.stubGlobal( + "fetch", + vi.fn( + (_url, init) => + new Promise((_resolve, reject) => + init.signal.addEventListener("abort", () => + reject(init.signal.reason), + ), + ), + ), + ); + const pending = new ObservabilityService( + {} as any, + {} as any, + ).getOperationalSnapshot(); + controller.abort(); + expect(await pending).toMatchObject({ status: "partial", processor: null }); + expect(timeout).toHaveBeenCalledWith(2500); + timeout.mockRestore(); + vi.unstubAllGlobals(); +}); diff --git a/docker-compose.observability.yml b/docker-compose.observability.yml index da21b77d..a8a88da5 100644 --- a/docker-compose.observability.yml +++ b/docker-compose.observability.yml @@ -3,7 +3,8 @@ services: image: prom/prometheus container_name: vagas-prometheus volumes: - - ./observability/prometheus/prometheus.yml:/etc/prometheus/prometheus.yml + - ./observability/prometheus/prometheus.yml:/etc/prometheus/prometheus.yml:ro + - ./observability/prometheus/rules:/etc/prometheus/rules:ro ports: - "9091:9090" networks: diff --git a/docker-compose.yml b/docker-compose.yml index b64ac9eb..b92079b9 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -22,6 +22,7 @@ services: - SCRAPER_PERSIST_BATCH_SIZE=${SCRAPER_PERSIST_BATCH_SIZE-100} - SCRAPER_INDEX_BATCH_SIZE=${SCRAPER_INDEX_BATCH_SIZE-250} - SCRAPER_CATALOG_LIFETIME=${SCRAPER_CATALOG_LIFETIME-216h} + - APPLICATION_VERSION=${APPLICATION_VERSION-unknown} - GOMAXPROCS=${GOMAXPROCS:-2} - GOMEMLIMIT=${GOMEMLIMIT:-1500MiB} - GUPY_ENABLED=${GUPY_ENABLED:-true} diff --git a/observability/prometheus/prometheus.yml b/observability/prometheus/prometheus.yml index 5f035af5..dfcfefe3 100644 --- a/observability/prometheus/prometheus.yml +++ b/observability/prometheus/prometheus.yml @@ -2,6 +2,15 @@ global: scrape_interval: 60s evaluation_interval: 60s +rule_files: + - /etc/prometheus/rules/recording.yml + - /etc/prometheus/rules/alerts.yml + +alerting: + alertmanagers: + - static_configs: + - targets: ["alertmanager:9093"] + scrape_configs: - job_name: backend static_configs: diff --git a/observability/prometheus/rules/alerts.yml b/observability/prometheus/rules/alerts.yml new file mode 100644 index 00000000..60e825b8 --- /dev/null +++ b/observability/prometheus/rules/alerts.yml @@ -0,0 +1,83 @@ +groups: + - name: candidate.operational.alerts + rules: + - alert: CandidateScraperHighCPU + expr: candidate_scraper:container_cpu_cores > 1.35 + for: 15m + labels: {severity: warning} + annotations: {summary: "Scraper uses over 90% of its 1.5 CPU quota for 15 minutes"} + - alert: CandidateScraperMemoryNearLimit + expr: candidate_scraper:container_memory_ratio > 0.85 + for: 10m + labels: {severity: warning} + annotations: {summary: "Scraper memory near the configured container limit"} + - alert: CandidateScraperRestarted + expr: changes(process_start_time_seconds{job="scraper-go"}[30m]) > 0 + for: 2m + labels: {severity: warning} + annotations: {summary: "Scraper process restarted; inspect container exit reason"} + - alert: CandidateScraperGoroutinesGrowing + expr: go_goroutines{job="scraper-go"} > 200 and delta(go_goroutines{job="scraper-go"}[30m]) > 100 + for: 15m + labels: {severity: warning} + annotations: {summary: "Sustained abnormal goroutine growth"} + - alert: CandidateScraperLockStuck + expr: candidate_scraper_lock_held == 1 and (time() - candidate_scraper_run_started_timestamp_seconds) > 3600 + for: 10m + labels: {severity: critical} + annotations: {summary: "Scraper lock held for over one hour"} + - alert: CandidateScraperLockLoss + expr: sum by (job) (increase(candidate_scraper_lock_lost_total[30m])) > 1 + for: 2m + labels: {severity: critical} + annotations: {summary: "Repeated distributed lock loss"} + - alert: CandidateScraperNoProgress + expr: candidate_scraper_running == 1 and (time() - candidate_scraper_last_progress_timestamp_seconds) > 600 + for: 5m + labels: {severity: warning} + annotations: {summary: "Active scraper has no task or batch progress"} + - alert: CandidateScraperCronWithoutSuccess + expr: (time() - (max by (job, instance) (candidate_scraper_last_run_timestamp_seconds{source="cron",status="success"} > 0) or on (job, instance) process_start_time_seconds{job="scraper-go"})) > on (job, instance) (candidate_scraper_cron_interval_seconds * 2) + for: 15m + labels: {severity: warning} + annotations: {summary: "No cron success for two configured intervals"} + - alert: CandidateScraperProviderTimeouts + expr: candidate_scraper:provider_timeout_ratio > 0.2 and on (job, provider) sum by (job, provider) (increase(candidate_scraper_provider_runs_total[15m])) >= 5 + for: 10m + labels: {severity: warning} + annotations: {summary: "Provider timeout ratio exceeds 20%"} + - alert: CandidateScraperPersistenceFailure + expr: sum by (job) (increase(candidate_scraper_persistence_batches_total{status="failed"}[15m])) > 0 + for: 5m + labels: {severity: critical} + annotations: {summary: "PostgreSQL catalog persistence failures"} + - alert: CandidateScraperIndexFailure + expr: sum by (job) (increase(candidate_scraper_index_batches_total{status="failed"}[15m])) > 0 + for: 5m + labels: {severity: critical} + annotations: {summary: "Valkey index publication failed after persistence"} + - alert: CandidateScraperReconciliationDivergence + expr: sum by (job) (candidate_scraper_index_reconciliation_divergences) > 0 + for: 10m + labels: {severity: warning} + annotations: {summary: "Explicit PostgreSQL versus Valkey reconciliation found divergence"} + - alert: CandidateScraperMaintenanceFailure + expr: sum by (job, operation) (increase(candidate_scraper_index_maintenance_runs_total{status="failed"}[30m])) > 0 + for: 5m + labels: {severity: warning} + annotations: {summary: "Catalog maintenance failed"} + - alert: CandidateJobsSearchLatency + expr: candidate_jobs:search_latency_p95_seconds > 0.5 + for: 10m + labels: {severity: warning} + annotations: {summary: "Jobs search p95 exceeds the 500 ms operational target"} + - alert: CandidateAdminLatency + expr: candidate_backend:admin_latency_p95_seconds > 1 + for: 10m + labels: {severity: warning} + annotations: {summary: "Administrative API p95 exceeds one second"} + - alert: CandidateBackendErrorRate + expr: candidate_backend:error_ratio > 0.05 and on (job) sum by (job) (increase(http_requests_total[5m])) >= 20 + for: 10m + labels: {severity: critical} + annotations: {summary: "Backend 5xx ratio exceeds 5%"} diff --git a/observability/prometheus/rules/recording.yml b/observability/prometheus/rules/recording.yml new file mode 100644 index 00000000..b239f41d --- /dev/null +++ b/observability/prometheus/rules/recording.yml @@ -0,0 +1,32 @@ +groups: + - name: candidate.operational.recording + interval: 60s + rules: + - record: candidate_jobs:search_latency_p95_seconds + expr: histogram_quantile(0.95, sum by (job, le) (rate(http_request_duration_seconds_bucket{route=~"(/api/v1)?/jobs/search"}[5m]))) + - record: candidate_backend:admin_latency_p95_seconds + expr: histogram_quantile(0.95, sum by (job, route, le) (rate(http_request_duration_seconds_bucket{route=~"(/api/v1)?/admin/(scrapers|observability)(/.*)?"}[5m]))) + - record: candidate_backend:error_ratio + expr: sum by (job) (rate(http_requests_total{status_code=~"5.."}[5m])) / clamp_min(sum by (job) (rate(http_requests_total[5m])), 0.001) + - record: candidate_scraper:cpu_cores + expr: sum by (job, instance) (rate(process_cpu_seconds_total{job="scraper-go"}[5m])) + - record: candidate_scraper:container_cpu_cores + expr: sum by (container_label_com_docker_compose_service) (rate(container_cpu_usage_seconds_total{container_label_com_docker_compose_service="scraper-go"}[5m])) + - record: candidate_scraper:container_memory_ratio + expr: sum by (container_label_com_docker_compose_service) (container_memory_working_set_bytes{container_label_com_docker_compose_service="scraper-go"}) / clamp_min(sum by (container_label_com_docker_compose_service) (container_spec_memory_limit_bytes{container_label_com_docker_compose_service="scraper-go"}), 1) + - record: candidate_scraper:rss_bytes + expr: process_resident_memory_bytes{job="scraper-go"} + - record: candidate_scraper:provider_duration_p95_seconds + expr: histogram_quantile(0.95, sum by (job, provider, le) (rate(candidate_scraper_provider_duration_seconds_bucket[15m]))) + - record: candidate_scraper:provider_error_ratio + expr: sum by (job, provider) (rate(candidate_scraper_provider_runs_total{status="failed"}[15m])) / clamp_min(sum by (job, provider) (rate(candidate_scraper_provider_runs_total[15m])), 0.001) + - record: candidate_scraper:provider_timeout_ratio + expr: sum by (job, provider) (rate(candidate_scraper_provider_runs_total{status="timeout"}[15m])) / clamp_min(sum by (job, provider) (rate(candidate_scraper_provider_runs_total[15m])), 0.001) + - record: candidate_jobs:search_cache_hit_ratio + expr: sum by (job) (rate(candidate_jobs_search_cache_requests_total{result="hit"}[5m])) / clamp_min(sum by (job) (rate(candidate_jobs_search_cache_requests_total{result=~"hit|miss|stale"}[5m])), 0.001) + - record: candidate_scraper:classification_approved_ratio + expr: sum by (job) (rate(candidate_scraper_classification_jobs_total{result="approved"}[15m])) / clamp_min(sum by (job) (rate(candidate_scraper_classification_jobs_total[15m])), 0.001) + - record: candidate_scraper:classification_rejected_ratio + expr: sum by (job) (rate(candidate_scraper_classification_jobs_total{result=~"rejected|other|invalid"}[15m])) / clamp_min(sum by (job) (rate(candidate_scraper_classification_jobs_total[15m])), 0.001) + - record: candidate_scraper:lock_conflicts_rate + expr: sum by (job, source) (rate(candidate_scraper_lock_conflicts_total[15m])) diff --git a/observability/prometheus/rules/tests.yml b/observability/prometheus/rules/tests.yml new file mode 100644 index 00000000..48c604e1 --- /dev/null +++ b/observability/prometheus/rules/tests.yml @@ -0,0 +1,51 @@ +# Loaded by promtool test rules only, not a Prometheus rule file. +rule_files: + - alerts.yml + - recording.yml +evaluation_interval: 1m +tests: + - name: sustained-cpu-and-search-under-budget + interval: 1m + input_series: + - series: 'container_cpu_usage_seconds_total{job="cadvisor",container_label_com_docker_compose_service="scraper-go"}' + values: '0+84x30' + - series: 'http_request_duration_seconds_bucket{job="backend",route="/jobs/search",le="0.1"}' + values: '0+5x30' + - series: 'http_request_duration_seconds_bucket{job="backend",route="/jobs/search",le="0.5"}' + values: '0+10x30' + - series: 'http_request_duration_seconds_bucket{job="backend",route="/jobs/search",le="+Inf"}' + values: '0+10x30' + alert_rule_test: + - eval_time: 10m + alertname: CandidateScraperHighCPU + exp_alerts: [] + - eval_time: 25m + alertname: CandidateScraperHighCPU + exp_alerts: + - exp_labels: {severity: warning, container_label_com_docker_compose_service: scraper-go} + exp_annotations: {summary: "Scraper uses over 90% of its 1.5 CPU quota for 15 minutes"} + - eval_time: 20m + alertname: CandidateJobsSearchLatency + exp_alerts: [] + promql_expr_test: + - expr: candidate_jobs:search_latency_p95_seconds + eval_time: 10m + exp_samples: + - labels: 'candidate_jobs:search_latency_p95_seconds{job="backend"}' + value: 0.4600000000000001 + - name: memory-sustained-not-brief + interval: 1m + input_series: + - series: 'container_memory_working_set_bytes{container_label_com_docker_compose_service="scraper-go"}' + values: '1900000000+0x30' + - series: 'container_spec_memory_limit_bytes{container_label_com_docker_compose_service="scraper-go"}' + values: '2147483648+0x30' + alert_rule_test: + - eval_time: 5m + alertname: CandidateScraperMemoryNearLimit + exp_alerts: [] + - eval_time: 15m + alertname: CandidateScraperMemoryNearLimit + exp_alerts: + - exp_labels: {severity: warning, container_label_com_docker_compose_service: scraper-go} + exp_annotations: {summary: "Scraper memory near the configured container limit"} diff --git a/scraper-go/cmd/server/observability.go b/scraper-go/cmd/server/observability.go new file mode 100644 index 00000000..9748ff41 --- /dev/null +++ b/scraper-go/cmd/server/observability.go @@ -0,0 +1,162 @@ +package main + +import ( + "context" + "database/sql" + "encoding/json" + "net/http" + "os" + "runtime" + "strconv" + "strings" + "sync" + "syscall" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" + "github.com/redis/go-redis/v9" +) + +type dependencyHealth struct { + Status string `json:"status"` +} +type operationalResources struct { + CPUPercent *float64 `json:"cpuPercent"` + CPUSeconds float64 `json:"cpuSeconds"` + MemoryBytes *uint64 `json:"memoryBytes"` + HeapBytes uint64 `json:"heapBytes"` + Goroutines int `json:"goroutines"` + GOMAXPROCS int `json:"gomaxprocs"` + GOMEMLIMITBytes int64 `json:"gomemlimitBytes"` +} + +type operationalIndex struct { + ActiveVersion string `json:"activeVersion"` + Maintenance *metrics.MaintenanceSummary `json:"maintenance"` + RebuildProgress *int64 `json:"rebuildProgress"` +} + +// Separate small pool: diagnostic deadlines must also constrain Redis I/O, +// without changing retries/timeouts of catalog persistence and index writes. +func observabilityRedisClient(source *redis.Client) *redis.Client { + opts := *source.Options() + opts.Dialer = nil + opts.DialerRetries = 1 + opts.PushNotificationProcessor = nil + opts.ContextTimeoutEnabled = true + opts.MaxRetries = -1 + opts.DialTimeout = 2 * time.Second + opts.ReadTimeout = 2 * time.Second + opts.WriteTimeout = 2 * time.Second + opts.PoolTimeout = 2 * time.Second + opts.PoolSize = 2 + opts.MaxConcurrentDials = 2 + opts.MaxActiveConns = 2 + opts.MaxIdleConns = 2 + opts.MinIdleConns = 0 + return redis.NewClient(&opts) +} + +var cpuSample = struct { + sync.Mutex + at time.Time + seconds float64 + percent *float64 +}{} + +func resources() operationalResources { + var mem runtime.MemStats + runtime.ReadMemStats(&mem) + var usage syscall.Rusage + _ = syscall.Getrusage(syscall.RUSAGE_SELF, &usage) + r := operationalResources{CPUSeconds: float64(usage.Utime.Sec+usage.Stime.Sec) + float64(usage.Utime.Usec+usage.Stime.Usec)/1e6, HeapBytes: mem.HeapAlloc, Goroutines: runtime.NumGoroutine()} + r.GOMAXPROCS, r.GOMEMLIMITBytes = metrics.RuntimeSettings() + cpuSample.Lock() + now := time.Now() + elapsed := now.Sub(cpuSample.at).Seconds() + if !cpuSample.at.IsZero() && elapsed >= .1 { + v := max(0, (r.CPUSeconds-cpuSample.seconds)/elapsed*100) + cpuSample.percent = &v + } + r.CPUPercent = cpuSample.percent + cpuSample.at = now + cpuSample.seconds = r.CPUSeconds + cpuSample.Unlock() + if raw, e := os.ReadFile("/proc/self/statm"); e == nil { + parts := strings.Fields(string(raw)) + if len(parts) > 1 { + if pages, e := strconv.ParseUint(parts[1], 10, 64); e == nil { + bytes := pages * uint64(os.Getpagesize()) + r.MemoryBytes = &bytes + } + } + } + return r +} + +// Internal technical status only. Authentication and RBAC remain in Node. +// Every dependency probe shares the request deadline and is joined before return. +func handleOperationalSnapshot(db *sql.DB, rdb *redis.Client) http.HandlerFunc { + return func(w http.ResponseWriter, r *http.Request) { + ctx, cancel := context.WithTimeout(r.Context(), 2*time.Second) + defer cancel() + pg, vk := dependencyHealth{"down"}, dependencyHealth{"down"} + version := "" + var maintenance *metrics.MaintenanceSummary + var rebuildProgress *int64 + var wg sync.WaitGroup + wg.Add(2) + go func() { + defer wg.Done() + if db != nil && db.PingContext(ctx) == nil { + pg.Status = "ok" + } + }() + go func() { + defer wg.Done() + if rdb == nil { + return + } + pipe := rdb.Pipeline() + ping := pipe.Ping(ctx) + active := pipe.Get(ctx, "scraper:jobs:index-version") + summary := pipe.Get(ctx, "scraper:observability:maintenance") + progress := pipe.HGet(ctx, metrics.MaintenanceMetricsKey, "rebuildProgress") + _, err := pipe.Exec(ctx) + + if ping.Err() == nil { + vk.Status = "ok" + if err != nil && err != redis.Nil { + vk.Status = "degraded" + } + } + version = active.Val() + if n, e := strconv.ParseInt(progress.Val(), 10, 64); e == nil && n >= 0 { + rebuildProgress = &n + } + if summary.Err() == nil { + var parsed metrics.MaintenanceSummary + if json.Unmarshal([]byte(summary.Val()), &parsed) == nil && parsed.Valid() { + maintenance = &parsed + } else if vk.Status == "ok" { + vk.Status = "degraded" + } + } + }() + wg.Wait() + status := "ok" + if pg.Status != "ok" || vk.Status != "ok" { + status = "partial" + } + w.Header().Set("Content-Type", "application/json") + w.Header().Set("Cache-Control", "no-store") + json.NewEncoder(w).Encode(struct { + metrics.Snapshot + Status string `json:"status"` + Timestamp time.Time `json:"timestamp"` + Resources operationalResources `json:"resources"` + Dependencies map[string]dependencyHealth `json:"dependencies"` + Index operationalIndex `json:"index"` + }{Snapshot: metrics.Current(), Status: status, Timestamp: time.Now().UTC(), Resources: resources(), Dependencies: map[string]dependencyHealth{"postgres": pg, "valkey": vk}, Index: operationalIndex{version, maintenance, rebuildProgress}}) + } +} diff --git a/scraper-go/cmd/server/observability_test.go b/scraper-go/cmd/server/observability_test.go new file mode 100644 index 00000000..4f13beb9 --- /dev/null +++ b/scraper-go/cmd/server/observability_test.go @@ -0,0 +1,107 @@ +package main + +import ( + "context" + "encoding/json" + "io" + "net" + "net/http/httptest" + "strings" + "testing" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" + "github.com/alicebob/miniredis/v2" + "github.com/redis/go-redis/v9" +) + +func TestOperationalSnapshotPartialResourcesAndNoSecrets(t *testing.T) { + metrics.StartRun("cron", time.Now()) + metrics.LockAcquired(time.Second) + r := httptest.NewRecorder() + handleOperationalSnapshot(nil, nil)(r, httptest.NewRequest("GET", "/admin/observability", nil)) + if r.Code != 200 { + t.Fatal(r.Code) + } + var body struct { + Status string + Execution metrics.Execution + Resources operationalResources + Lock metrics.Lock + } + if err := json.Unmarshal(r.Body.Bytes(), &body); err != nil { + t.Fatal(err) + } + if body.Status != "partial" || body.Execution.Status != "running" || body.Resources.Goroutines < 1 || !body.Lock.Held { + t.Fatal(r.Body.String()) + } + if strings.Contains(r.Body.String(), "token") || strings.Contains(r.Body.String(), "runId") { + t.Fatal("secret exposure") + } + metrics.LockReleased() + metrics.FinishRun(nil) + r = httptest.NewRecorder() + handleOperationalSnapshot(nil, nil)(r, httptest.NewRequest("GET", "/admin/observability", nil)) + if err := json.Unmarshal(r.Body.Bytes(), &body); err != nil { + t.Fatal(err) + } + if body.Execution.LastStatus == nil || *body.Execution.LastStatus != "success" { + t.Fatal("last run missing") + } +} + +func TestOperationalSnapshotSanitizesMaintenanceAndKeepsPartialFields(t *testing.T) { + mr := miniredis.RunT(t) + rdb := redis.NewClient(&redis.Options{Addr: mr.Addr(), ContextTimeoutEnabled: true}) + defer rdb.Close() + for _, raw := range []string{ + `{"operation":"reconcile","status":"success","finishedAt":"2026-10-07T00:00:00Z","durationSeconds":1,"processed":2,"divergences":0,"token":"private-secret"}`, + `{"token":"private-secret"}`, + } { + mr.Set("scraper:observability:maintenance", raw) + response := httptest.NewRecorder() + handleOperationalSnapshot(nil, rdb)(response, httptest.NewRequest("GET", "/admin/observability", nil)) + if strings.Contains(response.Body.String(), "private-secret") || !strings.Contains(response.Body.String(), `"resources":`) { + t.Fatal("maintenance payload escaped sanitization or hid available resources") + } + if raw == `{"token":"private-secret"}` && !strings.Contains(response.Body.String(), `"valkey":{"status":"degraded"}`) { + t.Fatal("invalid maintenance metadata was not marked partially unavailable") + } + } +} + +func TestOperationalSnapshotRedisDeadlineDoesNotChangeCatalogClient(t *testing.T) { + listener, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + defer listener.Close() + done := make(chan struct{}) + go func() { + defer close(done) + connection, err := listener.Accept() + if err == nil { + defer connection.Close() + connection.SetReadDeadline(time.Now().Add(time.Second)) + io.Copy(io.Discard, connection) // Accept Redis requests, never respond. + } + }() + source := redis.NewClient(&redis.Options{Addr: listener.Addr().String()}) + defer source.Close() + diagnostic := observabilityRedisClient(source) + defer diagnostic.Close() + if source.Options().ContextTimeoutEnabled || !diagnostic.Options().ContextTimeoutEnabled || diagnostic.Options().MaxRetries != 0 { + t.Fatal("diagnostic pool changed the catalog client") + } + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + response := httptest.NewRecorder() + started := time.Now() + handleOperationalSnapshot(nil, diagnostic)(response, httptest.NewRequest("GET", "/admin/observability", nil).WithContext(ctx)) + if time.Since(started) > time.Second || response.Code != 200 || !strings.Contains(response.Body.String(), `"status":"partial"`) { + t.Fatal("dependency deadline did not yield a partial snapshot") + } + diagnostic.Close() + listener.Close() + <-done +} diff --git a/scraper-go/cmd/server/server.go b/scraper-go/cmd/server/server.go index 637e7ba0..363a8b02 100644 --- a/scraper-go/cmd/server/server.go +++ b/scraper-go/cmd/server/server.go @@ -20,6 +20,7 @@ import ( "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobindex" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobstore" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/keywords" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/ports" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/runlock" "github.com/prometheus/client_golang/prometheus/promhttp" @@ -116,6 +117,8 @@ func run(adapterList []ports.JobSource, runtimeCfg config.RuntimeConfig) { schedulerCfg.ClassificationBatchSize = runtimeCfg.ClassificationBatchSize schedulerCfg.PersistBatchSize = runtimeCfg.PersistBatchSize schedulerCfg.IndexBatchSize = runtimeCfg.IndexBatchSize + metrics.SetConfiguredConcurrency(runtimeCfg.MaxConcurrency) + metrics.SetVersion(runtimeCfg.ApplicationVersion) scheduler := cronjob.New(schedulerCfg, kwStore, jobStore, adapterList, rdb, runLock) scheduler.BeforeRun = func(ctx context.Context) error { @@ -130,6 +133,10 @@ func run(adapterList []ports.JobSource, runtimeCfg config.RuntimeConfig) { bgCtx, bgCancel := context.WithCancel(context.Background()) defer bgCancel() + metricsRDB := observabilityRedisClient(rdb) + defer metricsRDB.Close() + stopMetricsSampler := metrics.StartMaintenanceSampler(bgCtx, metricsRDB) + defer stopMetricsSampler() // ── Rotas ── mux := http.NewServeMux() @@ -142,6 +149,7 @@ func run(adapterList []ports.JobSource, runtimeCfg config.RuntimeConfig) { mux.Handle("POST /api/keywords", handleSaveKeywords(kwStore)) // Administrativas + mux.Handle("GET /admin/observability", handleOperationalSnapshot(db, metricsRDB)) mux.Handle("POST /admin/scrape", handleTriggerScrape(scheduler, bgCtx)) mux.Handle("GET /admin/scrape/status", handleScraperStatus(scheduler)) mux.Handle("GET /admin/jobs", handleGetJobs(jobStore)) diff --git a/scraper-go/go.mod b/scraper-go/go.mod index 41e7c5de..ebeac3e8 100644 --- a/scraper-go/go.mod +++ b/scraper-go/go.mod @@ -17,6 +17,7 @@ require ( github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/davecgh/go-spew v1.1.1 // indirect github.com/kr/text v0.2.0 // indirect + github.com/kylelemons/godebug v1.1.0 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/pmezard/go-difflib v1.0.0 // indirect github.com/prometheus/client_model v0.6.2 // indirect diff --git a/scraper-go/internal/catalog/store.go b/scraper-go/internal/catalog/store.go index 5b190be5..949f2663 100644 --- a/scraper-go/internal/catalog/store.go +++ b/scraper-go/internal/catalog/store.go @@ -13,6 +13,7 @@ import ( "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/config" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobstore" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/lib/pq" ) @@ -38,8 +39,11 @@ func (s *Store) SaveBatch(ctx context.Context, jobs []domain.Job) (jobstore.Save func (s *Store) Import(ctx context.Context, jobs []domain.Job) (jobstore.SaveResult, error) { return s.save(ctx, jobs, true) } -func (s *Store) save(ctx context.Context, jobs []domain.Job, importing bool) (jobstore.SaveResult, error) { - result := jobstore.SaveResult{} +func (s *Store) save(ctx context.Context, jobs []domain.Job, importing bool) (result jobstore.SaveResult, returnErr error) { + started := time.Now() + defer func() { + metrics.ObservePersistence(started, len(jobs), result.Inserted, result.Updated, len(jobs)-len(result.Persisted), returnErr) + }() if len(jobs) > 2500 { return result, fmt.Errorf("catalog batch exceeds 2500") } @@ -75,6 +79,11 @@ func (s *Store) save(ctx context.Context, jobs []domain.Job, importing bool) (jo return result, fmt.Errorf("catalog begin: %w", err) } defer tx.Rollback() + defer func() { + if returnErr != nil { + metrics.PersistenceRollbacks.WithLabelValues(metrics.PersistenceErrorReason(returnErr)).Inc() + } + }() // Fence absent IDs as well, so concurrent inserts preserve merge semantics. if _, err = tx.ExecContext(ctx, `SELECT pg_advisory_xact_lock(hashtextextended(id,125)) FROM (SELECT unnest($1::text[]) AS id ORDER BY 1) AS ordered_ids`, pq.Array(ids)); err != nil { return result, err @@ -148,11 +157,13 @@ func (s *Store) save(ctx context.Context, jobs []domain.Job, importing bool) (jo if err = tx.Commit(); err != nil { return jobstore.SaveResult{Invalid: result.Invalid}, fmt.Errorf("catalog commit: %w", err) } - for _, j := range persisted { + for i, j := range persisted { if _, ok := existing[j.ID]; ok { result.Updated++ + persisted[i].CatalogChange = "job_updated" } else { result.Inserted++ + persisted[i].CatalogChange = "job_created" } } result.Persisted = persisted @@ -264,6 +275,9 @@ func (s *Store) Deactivate(ctx context.Context, ids []string) ([]domain.Job, err if err = tx.Commit(); err != nil { return nil, err } + for i := range jobs { + jobs[i].CatalogChange = "job_removed" + } return jobs, nil } @@ -309,6 +323,9 @@ func (s *Store) ReclassifyBatch(ctx context.Context, jobs []domain.Job) ([]domai if err = tx.Commit(); err != nil { return nil, fmt.Errorf("catalog commit: %w", err) } + for i := range persisted { + persisted[i].CatalogChange = "job_reclassified" + } return persisted, nil } diff --git a/scraper-go/internal/catalogops/maintenance.go b/scraper-go/internal/catalogops/maintenance.go index 2d2f3d07..eb5d088d 100644 --- a/scraper-go/internal/catalogops/maintenance.go +++ b/scraper-go/internal/catalogops/maintenance.go @@ -16,6 +16,7 @@ import ( "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/classifier" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobindex" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/pipeline" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" "github.com/redis/go-redis/v9" @@ -67,7 +68,11 @@ func (m *Maintenance) Rebuild(ctx context.Context) (string, error) { defer release() return m.rebuildLocked(ctx) } -func (m *Maintenance) rebuildLocked(ctx context.Context) (string, error) { +func (m *Maintenance) rebuildLocked(ctx context.Context) (result string, returnErr error) { + started := time.Now() + processed := 0 + defer func() { m.record(ctx, "rebuild", started, processed, Report{}, returnErr) }() + m.progress(ctx, 0) bytes := make([]byte, 12) if _, err := rand.Read(bytes); err != nil { return "", err @@ -101,6 +106,8 @@ func (m *Maintenance) rebuildLocked(ctx context.Context) (string, error) { } cursor = jobs[len(jobs)-1].ID total += len(jobs) + processed = total + m.progress(ctx, total) slog.Info("catalog rebuild batch", "version", version, "batch_size", len(jobs), "processed", total) } report, err := Compare(ctx, m.Store, m.Index, version, m.size(), m.keys) @@ -117,10 +124,12 @@ func (m *Maintenance) rebuildLocked(ctx context.Context) (string, error) { } } raw, _ := json.Marshal(familyKeys) - _, err = publish.Run(ctx, m.Index.RDB, []string{jobindex.ActiveKey, jobindex.GenerationKey}, previous, version, jobindex.Prefix(version), string(raw)).Result() + publishStarted := time.Now() + _, err = publish.Run(ctx, m.Index.RDB, []string{jobindex.ActiveKey, jobindex.GenerationKey}, previous, version, jobindex.Prefix(version), string(raw), taxonomy.Version()).Result() if err != nil { return "", fmt.Errorf("publish catalog namespace: %w", err) } + metrics.CacheInvalidationDuration.WithLabelValues("invalidate").Observe(time.Since(publishStarted).Seconds()) // Record only revisions belonging to the successfully published projection. cursor = "" @@ -137,6 +146,7 @@ func (m *Maintenance) rebuildLocked(ctx context.Context) (string, error) { } cursor = jobs[len(jobs)-1].ID } + slog.Info("catalog rebuild published", "version", version, "previous_version", previous, "active", report.Active) return version, nil } @@ -144,7 +154,9 @@ func (m *Maintenance) rebuildLocked(ctx context.Context) (string, error) { var publish = redis.NewScript(` local previous,version,prefix,families=ARGV[1],ARGV[2],ARGV[3],cjson.decode(ARGV[4]) local function typed(k,want) local t=redis.call('TYPE',k).ok;if t~='none' and t~=want then error('WRONGTYPE rebuild preflight') end end -typed(KEYS[1],'string');typed(KEYS[2],'string');typed('scraper:jobs:previous-index-version','string') +typed(KEYS[1],'string');typed(KEYS[2],'string');typed('scraper:jobs:previous-index-version','string');typed('scraper:jobs:taxonomy-version','string') +local telemetryType=redis.call('TYPE','scraper:observability:maintenance-metrics').ok;local telemetryOk=telemetryType=='none' or telemetryType=='hash' +if telemetryOk then for _,reason in ipairs({'job_created','job_updated','job_removed','job_reclassified','index_rebuilt','taxonomy_changed'}) do local v=redis.call('HGET','scraper:observability:maintenance-metrics','cache:'..reason);if v and (not string.match(v,'^%d+$') or tonumber(v)>=9007199254740991) then telemetryOk=false end end end if (redis.call('GET',KEYS[1]) or 'bootstrap')~=previous then return redis.error_reply('active namespace changed') end local g=redis.call('GET',KEYS[2]);if g and (not string.match(g,'^%d+$') or tonumber(g)>=9007199254740991) then error('invalid generation') end typed(prefix..'keys','set');typed(prefix..'index','set');typed(prefix..'expires','zset');typed('scraper:jobs:index','set');typed('scraper:jobs:expires','zset') @@ -154,10 +166,18 @@ redis.call('SUNIONSTORE','scraper:jobs:index',prefix..'index') redis.call('ZUNIONSTORE','scraper:jobs:expires',1,prefix..'expires') redis.call('SET','scraper:jobs:previous-index-version',previous) redis.call('PERSIST',prefix..'keys');redis.call('PERSIST',prefix..'index');redis.call('PERSIST',prefix..'expires'); -redis.call('SET',KEYS[1],version);redis.call('INCR',KEYS[2]);return 1 +redis.call('SET',KEYS[1],version);redis.call('INCR',KEYS[2]);if telemetryOk then redis.call('HINCRBY','scraper:observability:maintenance-metrics','cache:index_rebuilt',1) end;local old=redis.call('GET','scraper:jobs:taxonomy-version');if telemetryOk and old and old~=ARGV[5] then redis.call('HINCRBY','scraper:observability:maintenance-metrics','cache:taxonomy_changed',1) end;redis.call('SET','scraper:jobs:taxonomy-version',ARGV[5]);return 1 `) -func (m *Maintenance) Reconcile(ctx context.Context, fix bool) (Report, error) { +func (m *Maintenance) Reconcile(ctx context.Context, fix bool) (result Report, returnErr error) { + started := time.Now() + defer func() { + if fix && returnErr == nil { + m.record(ctx, "reconcile", started, result.Active, result, returnErr, Report{Active: result.Active}) + } else { + m.record(ctx, "reconcile", started, result.Active, result, returnErr) + } + }() release, err := m.Store.MaintenanceLease(ctx) if err != nil { return Report{}, err @@ -424,7 +444,9 @@ var cleanup = redis.NewScript(`if (redis.call('GET',KEYS[1]) or 'bootstrap')==AR // Backfill uses SCAN of document keys, pipelined GET/PTTL and SQL batch import. // It does not renew old TTLs or overwrite a row already present in PostgreSQL. -func (m *Maintenance) Backfill(ctx context.Context) (int, int, error) { +func (m *Maintenance) Backfill(ctx context.Context) (resultN int, resultInvalid int, returnErr error) { + started := time.Now() + defer func() { m.record(ctx, "backfill", started, resultN, Report{}, returnErr) }() release, err := m.Store.MaintenanceLease(ctx) if err != nil { return 0, 0, err @@ -502,7 +524,9 @@ func (m *Maintenance) Backfill(ctx context.Context) (int, int, error) { // Expire applies committed PostgreSQL expirations in bounded batches. It never // deletes historical SQL rows, and repeated runs do not bump cache generation. -func (m *Maintenance) Expire(ctx context.Context) (int, error) { +func (m *Maintenance) Expire(ctx context.Context) (resultN int, returnErr error) { + started := time.Now() + defer func() { m.record(ctx, "expire", started, resultN, Report{}, returnErr) }() release, err := m.Store.ProcessingLease(ctx) if err != nil { return 0, err @@ -554,7 +578,9 @@ func (m *Maintenance) Expire(ctx context.Context) (int, error) { // Reclassify is explicit, independent of external collection, and never renews // lastSeenAt/expiresAt. Its exclusive fence prevents stale payload overwrites. -func (m *Maintenance) Reclassify(ctx context.Context) (int, error) { +func (m *Maintenance) Reclassify(ctx context.Context) (resultN int, returnErr error) { + started := time.Now() + defer func() { m.record(ctx, "reclassify", started, resultN, Report{}, returnErr) }() release, err := m.Store.MaintenanceLease(ctx) if err != nil { return 0, err @@ -610,7 +636,9 @@ func (m *Maintenance) Reclassify(ctx context.Context) (int, error) { // Rollback only activates an already existing namespace if it still matches // the PostgreSQL truth. Changed catalog rows require a new rebuild instead. -func (m *Maintenance) Rollback(ctx context.Context, version string) error { +func (m *Maintenance) Rollback(ctx context.Context, version string) (returnErr error) { + started := time.Now() + defer func() { m.record(ctx, "rollback", started, 0, Report{}, returnErr) }() release, err := m.Store.MaintenanceLease(ctx) if err != nil { return err @@ -646,6 +674,10 @@ func (m *Maintenance) Rollback(ctx context.Context, version string) error { } } raw, _ := json.Marshal(familyKeys) - _, err = publish.Run(ctx, m.Index.RDB, []string{jobindex.ActiveKey, jobindex.GenerationKey}, previous, version, jobindex.Prefix(version), string(raw)).Result() + publishStarted := time.Now() + _, err = publish.Run(ctx, m.Index.RDB, []string{jobindex.ActiveKey, jobindex.GenerationKey}, previous, version, jobindex.Prefix(version), string(raw), taxonomy.Version()).Result() + if err == nil { + metrics.CacheInvalidationDuration.WithLabelValues("invalidate").Observe(time.Since(publishStarted).Seconds()) + } return err } diff --git a/scraper-go/internal/catalogops/observability.go b/scraper-go/internal/catalogops/observability.go new file mode 100644 index 00000000..35059e67 --- /dev/null +++ b/scraper-go/internal/catalogops/observability.go @@ -0,0 +1,69 @@ +package catalogops + +import ( + "context" + "encoding/json" + "log/slog" + "strconv" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" +) + +type maintenanceSummary = metrics.MaintenanceSummary + +func (m *Maintenance) record(ctx context.Context, operation string, started time.Time, processed int, report Report, err error, remaining ...Report) { + duration := time.Since(started).Seconds() + status := metrics.BatchStatus(err) + fields := map[string]int{"missing": report.Missing, "stale": report.Stale, "membership": report.Membership, "primary": report.Primary, "related": report.Related, "any": report.Any, "invalid": report.Invalid, "documents": report.Documents, "counts": report.Counts} + divergent := 0 + for _, v := range fields { + divergent += v + } + raw, _ := json.Marshal(maintenanceSummary{ + Operation: operation, Status: status, DurationSeconds: duration, + FinishedAt: time.Now().UTC(), Processed: max(0, processed), Divergences: divergent, + }) + // Telemetry cleanup has a bounded independent deadline after cancellation; + // it cannot change commit/publication success or trigger a catalog retry. + recordCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), 2*time.Second) + defer cancel() + pipe := m.Index.RDB.TxPipeline() + prefix := operation + ":" + status + ":" + key := metrics.MaintenanceMetricsKey + pipe.HIncrBy(recordCtx, key, prefix+"count", 1) + pipe.HIncrByFloat(recordCtx, key, prefix+"sum", duration) + for _, b := range metrics.MaintenanceBuckets { + if duration <= b { + pipe.HIncrBy(recordCtx, key, prefix+strconv.FormatFloat(b, 'g', -1, 64), 1) + } + } + if operation == "reconcile" { + result := "consistent" + if divergent > 0 { + result = "divergent" + } + if err != nil { + result = status + } + pipe.HIncrBy(recordCtx, key, "reconcile:"+result, 1) + if len(remaining) > 0 { + r := remaining[0] + fields = map[string]int{"missing": r.Missing, "stale": r.Stale, "membership": r.Membership, "primary": r.Primary, "related": r.Related, "any": r.Any, "invalid": r.Invalid, "documents": r.Documents, "counts": r.Counts} + } + for k, v := range fields { + pipe.HSet(recordCtx, key, "divergence:"+k, v) + } + } + pipe.Set(recordCtx, "scraper:observability:maintenance", raw, 24*time.Hour) + if _, e := pipe.Exec(recordCtx); e != nil { + slog.Warn("maintenance telemetry unavailable", "operation", operation, "errorType", metrics.ErrorType(e)) + } + slog.Info("catalog maintenance completed", "operation", operation, "status", status, "duration", duration, "processed", processed, "divergences", divergent) +} +func (m *Maintenance) progress(ctx context.Context, n int) { + metrics.RebuildProgress.Set(float64(n)) + if e := m.Index.RDB.HSet(ctx, metrics.MaintenanceMetricsKey, "rebuildProgress", n).Err(); e != nil { + slog.Warn("maintenance progress telemetry unavailable", "errorType", metrics.ErrorType(e)) + } +} diff --git a/scraper-go/internal/catalogops/observability_test.go b/scraper-go/internal/catalogops/observability_test.go new file mode 100644 index 00000000..0ae64061 --- /dev/null +++ b/scraper-go/internal/catalogops/observability_test.go @@ -0,0 +1,59 @@ +package catalogops + +import ( + "context" + "encoding/json" + "testing" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobindex" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" + "github.com/alicebob/miniredis/v2" + "github.com/prometheus/client_golang/prometheus" + "github.com/redis/go-redis/v9" +) + +func TestMaintenanceTelemetrySurvivesCLIAndKeepsCatalogReadOnly(t *testing.T) { + mr := miniredis.RunT(t) + rdb := redis.NewClient(&redis.Options{Addr: mr.Addr()}) + defer rdb.Close() + ctx := context.Background() + m := Maintenance{Index: jobindex.New(rdb)} + rdb.Set(ctx, "scraper:jobs:index-version", "existing", 0) + m.record(ctx, "reconcile", time.Now().Add(-time.Second), 3, Report{Missing: 2, Related: 1}, nil) + if got := rdb.HGet(ctx, metrics.MaintenanceMetricsKey, "reconcile:divergent").Val(); got != "1" { + t.Fatal(got) + } + if rdb.Get(ctx, "scraper:jobs:index-version").Val() != "existing" || rdb.Exists(ctx, jobindex.GenerationKey).Val() != 0 { + t.Fatal("telemetry changed catalog") + } + var summary maintenanceSummary + if e := json.Unmarshal([]byte(rdb.Get(ctx, "scraper:observability:maintenance").Val()), &summary); e != nil { + t.Fatal(e) + } + if summary.Divergences != 3 || summary.DurationSeconds < 1 || summary.Status != "success" { + t.Fatal(summary) + } + stopped := metrics.StartMaintenanceSampler(ctx, rdb) + defer stopped() + deadline := time.Now().Add(time.Second) + for time.Now().Before(deadline) { + families, err := prometheus.DefaultGatherer.Gather() + if err != nil { + t.Fatal(err) + } + for _, f := range families { + if f.GetName() == "candidate_scraper_index_reconciliation_total" { + for _, item := range f.Metric { + for _, label := range item.Label { + if label.GetName() == "result" && label.GetValue() == "divergent" && item.GetCounter().GetValue() == 1 { + return + } + } + } + } + } + time.Sleep(time.Millisecond) + } + t.Fatal("durable observation missing") +} diff --git a/scraper-go/internal/classifier/classifier.go b/scraper-go/internal/classifier/classifier.go index 3e7d6c0e..6bfa3dd3 100644 --- a/scraper-go/internal/classifier/classifier.go +++ b/scraper-go/internal/classifier/classifier.go @@ -6,8 +6,10 @@ import ( "sort" "strconv" "strings" + "time" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" ) @@ -42,7 +44,9 @@ type sourceClassificationStats struct { // TaxonomyVersion identifies the contract used without changing persisted jobs. func TaxonomyVersion() string { return taxonomy.Version() } -func Classify(job domain.Job) domain.Classification { +func Classify(job domain.Job) (classification domain.Classification) { + started := time.Now() + defer func() { metrics.Classification(job, classification, started) }() text := normalizeText(strings.Join([]string{ job.Title, job.Company, diff --git a/scraper-go/internal/config/config.go b/scraper-go/internal/config/config.go index 0de3c0bb..ebf19af1 100644 --- a/scraper-go/internal/config/config.go +++ b/scraper-go/internal/config/config.go @@ -37,6 +37,7 @@ const ( ) type RuntimeConfig struct { + ApplicationVersion string CatalogLifetime time.Duration MaxConcurrency int MaxConcurrencySource string @@ -56,6 +57,7 @@ func LoadRuntimeConfig() (RuntimeConfig, error) { func LoadRuntimeConfigFromLookup(lookup func(string) (string, bool)) (RuntimeConfig, error) { cfg := RuntimeConfig{ + ApplicationVersion: "unknown", CatalogLifetime: DefaultCatalogLifetime, MaxConcurrency: DefaultMaxConcurrency, MaxConcurrencySource: SourceInternalDefault, @@ -69,6 +71,14 @@ func LoadRuntimeConfigFromLookup(lookup func(string) (string, bool)) (RuntimeCon IndexBatchSize: DefaultIndexBatchSize, } + if value, ok := lookup("APPLICATION_VERSION"); ok { + value = strings.TrimSpace(value) + if value == "" || len(value) > 128 || strings.ContainsAny(value, "\n\r") { + return RuntimeConfig{}, fmt.Errorf("APPLICATION_VERSION must contain 1..128 printable characters") + } + cfg.ApplicationVersion = value + } + if value, ok := lookup(ScraperMaxConcurrencyEnv); ok { parsed, err := positiveInt(ScraperMaxConcurrencyEnv, value) if err != nil { diff --git a/scraper-go/internal/config/config_test.go b/scraper-go/internal/config/config_test.go index 884376d1..b0ca3368 100644 --- a/scraper-go/internal/config/config_test.go +++ b/scraper-go/internal/config/config_test.go @@ -3,6 +3,7 @@ package config import ( "os" "path/filepath" + "strings" "testing" "time" @@ -363,3 +364,26 @@ func TestCatalogLifetimeConfiguration(t *testing.T) { } } } + +func TestApplicationVersionValidation(t *testing.T) { + for _, value := range []string{"", "bad\nversion", strings.Repeat("v", 129)} { + _, err := LoadRuntimeConfigFromLookup(func(k string) (string, bool) { + if k == "APPLICATION_VERSION" { + return value, true + } + return "", false + }) + if err == nil { + t.Fatal("invalid version accepted") + } + } + cfg, err := LoadRuntimeConfigFromLookup(func(k string) (string, bool) { + if k == "APPLICATION_VERSION" { + return "pav-126", true + } + return "", false + }) + if err != nil || cfg.ApplicationVersion != "pav-126" { + t.Fatal(cfg, err) + } +} diff --git a/scraper-go/internal/cronjob/cronjob.go b/scraper-go/internal/cronjob/cronjob.go index 5a4aac92..14928ae0 100644 --- a/scraper-go/internal/cronjob/cronjob.go +++ b/scraper-go/internal/cronjob/cronjob.go @@ -8,6 +8,8 @@ import ( "sync" "time" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" + "github.com/redis/go-redis/v9" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/config" @@ -90,17 +92,21 @@ func New( } func (s *Scheduler) Start(ctx context.Context) { + metrics.CronInterval.Set(s.cfg.Interval.Seconds()) slog.Info("cronjob: scheduler iniciado", "interval", s.cfg.Interval) go func() { s.runCron(ctx) + metrics.SetNextRun(time.Now().Add(s.cfg.Interval)) ticker := time.NewTicker(s.cfg.Interval) defer ticker.Stop() + defer metrics.SetNextRun(time.Time{}) for { select { case <-ticker.C: + metrics.SetNextRun(time.Now().Add(s.cfg.Interval)) s.runCron(ctx) case <-s.stop: slog.Info("cronjob: scheduler encerrado") @@ -213,6 +219,7 @@ func (s *Scheduler) acquire(ctx context.Context, source string) (*runlock.Lease, } func (s *Scheduler) runWithLease(lease *runlock.Lease) (runErr error) { + defer func() { metrics.FinishRun(runErr, lease.RunID()) }() s.mu.Lock() s.running = true s.mu.Unlock() diff --git a/scraper-go/internal/domain/job.go b/scraper-go/internal/domain/job.go index 5c7503ec..749a3624 100644 --- a/scraper-go/internal/domain/job.go +++ b/scraper-go/internal/domain/job.go @@ -3,6 +3,7 @@ package domain import "time" type Job struct { + CatalogChange string `json:"-"` CatalogRevision int64 `json:"-"` CatalogExpiresAt time.Time `json:"-"` ID string `json:"id"` diff --git a/scraper-go/internal/jobindex/index.go b/scraper-go/internal/jobindex/index.go index c94010e5..d435f27e 100644 --- a/scraper-go/internal/jobindex/index.go +++ b/scraper-go/internal/jobindex/index.go @@ -10,6 +10,7 @@ import ( "time" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" "github.com/redis/go-redis/v9" ) @@ -21,6 +22,7 @@ const Bootstrap = "bootstrap" func Prefix(version string) string { return "scraper:jobs:ns:" + version + ":" } type Plan struct { + Change string `json:"change,omitempty"` ID string `json:"id"` Revision int64 `json:"revision"` Expires int64 `json:"expiresAt"` @@ -36,7 +38,13 @@ func Build(job domain.Job, keys []string) (Plan, error) { if job.ID == "" || job.CatalogRevision < 1 || job.CatalogExpiresAt.IsZero() { return Plan{}, fmt.Errorf("index requires committed catalog identity, revision and expiry") } - p := Plan{ID: job.ID, Revision: job.CatalogRevision, Expires: job.CatalogExpiresAt.Unix(), Taxonomy: taxonomy.Version(), Keys: []string{}, Related: []string{}} + change := job.CatalogChange + switch change { + case "job_created", "job_updated", "job_removed", "job_reclassified": + default: + change = "job_updated" + } + p := Plan{Change: change, ID: job.ID, Revision: job.CatalogRevision, Expires: job.CatalogExpiresAt.Unix(), Taxonomy: taxonomy.Version(), Keys: []string{}, Related: []string{}} if c := job.Classification; c != nil { if c.PrimaryFamily != "other" && !taxonomy.IsPublic(c.PrimaryFamily) { return p, fmt.Errorf("invalid primary family in committed classification") @@ -98,13 +106,17 @@ func (m *Manager) Active(ctx context.Context) (string, error) { return v, e } func (m *Manager) Apply(ctx context.Context, jobs []domain.Job, keys func(domain.Job) []string) (int, error) { + started := time.Now() version, err := m.Active(ctx) if err != nil { + metrics.ObserveIndex(started, len(jobs), 0, err) return 0, err } return m.ApplyVersion(ctx, version, jobs, keys, false) } -func (m *Manager) ApplyVersion(ctx context.Context, version string, jobs []domain.Job, keys func(domain.Job) []string, draft bool) (int, error) { +func (m *Manager) ApplyVersion(ctx context.Context, version string, jobs []domain.Job, keys func(domain.Job) []string, draft bool) (changed int, returnErr error) { + started := time.Now() + defer func() { metrics.ObserveIndex(started, len(jobs), changed, returnErr) }() if len(jobs) > 2500 { return 0, fmt.Errorf("index batch exceeds 2500") } @@ -140,10 +152,15 @@ func (m *Manager) ApplyVersion(ctx context.Context, version string, jobs []domai if err != nil { return 0, err } + scriptStarted := time.Now() result, err := applyScript.Run(ctx, m.RDB, []string{ActiveKey, GenerationKey}, version, Prefix(version), string(raw), now, draft).Int() if err != nil { return 0, fmt.Errorf("atomic index batch: %w", err) } + + if !draft && result > 0 { + metrics.CacheInvalidationDuration.WithLabelValues("invalidate").Observe(time.Since(scriptStarted).Seconds()) + } return result, nil } @@ -156,7 +173,9 @@ local function typed(k,want) local t=redis.call('TYPE',k).ok if t~='none' and t~=want then error('WRONGTYPE controlled index preflight') end end -typed(KEYS[1],'string');typed(KEYS[2],'string') +typed(KEYS[1],'string');typed(KEYS[2],'string');typed('scraper:jobs:taxonomy-version','string') +local telemetryType=redis.call('TYPE','scraper:observability:maintenance-metrics').ok;local telemetryOk=telemetryType=='none' or telemetryType=='hash' +if telemetryOk then for _,reason in ipairs({'job_created','job_updated','job_removed','job_reclassified','index_rebuilt','taxonomy_changed'}) do local v=redis.call('HGET','scraper:observability:maintenance-metrics','cache:'..reason);if v and (not string.match(v,'^%d+$') or tonumber(v)>=9007199254740991) then telemetryOk=false end end end local g=redis.call('GET',KEYS[2]);if g and (not string.match(g,'^%d+$') or tonumber(g)>=9007199254740991) then error('invalid generation') end local active=redis.call('GET',KEYS[1]) or 'bootstrap' if not draft and active~=version then return redis.error_reply('index version changed') end @@ -181,7 +200,7 @@ for i,p in ipairs(plans) do for _,k in ipairs(p.keys) do typed(prefix..k,'set');if not draft then typed('scraper:jobs:'..k,'set') end end if not draft then typed('scraper:job:'..p.id,'string');typed('scraper:jobs:index-membership:'..p.id,'string');typed('scraper:job:'..p.id..':idx','set') end end -local changed=0 +local changed=0;local invalidations={} for i,p in ipairs(plans) do if tonumber(old[i].revision)0 or redis.call('SISMEMBER',prefix..'index',p.id)==1)) then for _,k in ipairs(old[i].keys) do @@ -222,8 +241,9 @@ for i,p in ipairs(plans) do for _,k in ipairs(p.keys) do redis.call('PERSIST',prefix..k) end end changed=changed+1 + if not draft then local reason=p.change;if not alive then reason='job_removed' end;invalidations[reason]=true end end end -if not draft and changed>0 then redis.call('SET',KEYS[1],version);redis.call('INCR',KEYS[2]) end +if not draft and changed>0 then redis.call('SET',KEYS[1],version);redis.call('INCR',KEYS[2]);if telemetryOk then for reason,_ in pairs(invalidations) do redis.call('HINCRBY','scraper:observability:maintenance-metrics','cache:'..reason,1) end end;local old=redis.call('GET','scraper:jobs:taxonomy-version');local tax=plans[1].taxonomyVersion;if telemetryOk and old and old~=tax then redis.call('HINCRBY','scraper:observability:maintenance-metrics','cache:taxonomy_changed',1) end;redis.call('SET','scraper:jobs:taxonomy-version',tax) end return changed `) diff --git a/scraper-go/internal/jobindex/index_test.go b/scraper-go/internal/jobindex/index_test.go index 69a15107..cefa85a1 100644 --- a/scraper-go/internal/jobindex/index_test.go +++ b/scraper-go/internal/jobindex/index_test.go @@ -5,8 +5,10 @@ import ( "encoding/json" "fmt" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" "github.com/alicebob/miniredis/v2" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/redis/go-redis/v9" "github.com/stretchr/testify/require" "os" @@ -205,3 +207,26 @@ func TestRealValkeyProjection(t *testing.T) { require.False(t, client.SIsMember(ctx, prefix+"family:product", "a").Val()) require.True(t, client.SIsMember(ctx, prefix+"family:primary:product_design", "a").Val()) } + +func TestInvalidTelemetryCannotBlockAtomicIndexPublication(t *testing.T) { + mr := miniredis.RunT(t) + rdb := redis.NewClient(&redis.Options{Addr: mr.Addr()}) + defer rdb.Close() + ctx := context.Background() + m := New(rdb) + j := domain.Job{ID: "telemetry-job", Title: "Backend", CatalogRevision: 1, CatalogExpiresAt: time.Now().Add(time.Hour), Classification: &domain.Classification{PrimaryFamily: "backend", InScope: true}} + require.NoError(t, rdb.Set(ctx, "scraper:observability:maintenance-metrics", "invalid-telemetry", 0).Err()) + _, err := m.Apply(ctx, []domain.Job{j}, func(domain.Job) []string { return nil }) + require.NoError(t, err) + require.True(t, rdb.SIsMember(ctx, Prefix(Bootstrap)+"family:primary:backend", j.ID).Val()) + require.Equal(t, "1", rdb.Get(ctx, GenerationKey).Val()) +} + +func TestIndexTelemetryIncludesActiveNamespaceLookupFailure(t *testing.T) { + m, client := setup(t) + client.Close() + before := testutil.ToFloat64(metrics.IndexBatches.WithLabelValues("failed")) + _, err := m.Apply(context.Background(), []domain.Job{committed("unindexed", "backend", nil, 1)}, noKeys) + require.Error(t, err) + require.Equal(t, before+1, testutil.ToFloat64(metrics.IndexBatches.WithLabelValues("failed"))) +} diff --git a/scraper-go/internal/jobstore/jobstore.go b/scraper-go/internal/jobstore/jobstore.go index ee507ec5..c42906a0 100644 --- a/scraper-go/internal/jobstore/jobstore.go +++ b/scraper-go/internal/jobstore/jobstore.go @@ -6,6 +6,8 @@ import ( "encoding/json" "errors" "fmt" + "golang.org/x/text/transform" + "golang.org/x/text/unicode/norm" "log/slog" "net/url" "strings" @@ -15,10 +17,9 @@ import ( "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/adapters/adapterutil" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/config" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/lib/pq" "github.com/redis/go-redis/v9" - "golang.org/x/text/transform" - "golang.org/x/text/unicode/norm" ) const ( @@ -52,7 +53,16 @@ type SaveResult struct { func (s *Store) SaveBatch(ctx context.Context, jobs []domain.Job) (SaveResult, error) { if s.catalog != nil { var result SaveResult - err := retryTransient(ctx, func() error { var err error; result, err = s.catalog.SaveBatch(ctx, jobs); return err }) + var previousErr error + err := retryTransient(ctx, func() error { + if previousErr != nil { + metrics.PersistenceRetries.WithLabelValues(metrics.PersistenceErrorReason(previousErr)).Inc() + } + var err error + result, err = s.catalog.SaveBatch(ctx, jobs) + previousErr = err + return err + }) return result, err } var result SaveResult diff --git a/scraper-go/internal/metrics/classification.go b/scraper-go/internal/metrics/classification.go new file mode 100644 index 00000000..48fabfba --- /dev/null +++ b/scraper-go/internal/metrics/classification.go @@ -0,0 +1,48 @@ +package metrics + +import ( + "strings" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" +) + +// Collapse free-text explanations into stable operational codes. Classification +// remains unchanged; title text is only kept in the bounded admin aggregate. +func Classification(job domain.Job, c domain.Classification, started time.Time) { + family := c.PrimaryFamily + if !taxonomy.IsPublic(family) && family != "other" { + family = "other" + } + result := "approved" + reason := "insufficient_title_evidence" + if !c.InScope { + result = "rejected" + for _, r := range c.Reasons { + s := strings.ToLower(r) + if strings.Contains(s, "nenhuma familia") { + reason = "no_family_recognized" + result = "other" + break + } + if strings.Contains(s, "administrativ") || strings.Contains(s, "negativ") || strings.Contains(s, "nao tecnic") || strings.Contains(s, "producao") || strings.Contains(s, "operacion") { + reason = "negative_title" + } + } + } + ClassificationJobs.WithLabelValues(result, family).Inc() + ClassificationDuration.WithLabelValues(result).Observe(time.Since(started).Seconds()) + if !c.InScope { + ClassificationRejections.WithLabelValues(family, reason).Inc() + RejectTitle(job.Title, reason) + JobResult(job.Source, "rejected", 1) + } else { + JobResult(job.Source, "approved", 1) + } +} +func InvalidJob(provider string) { + ClassificationJobs.WithLabelValues("invalid", "other").Inc() + ClassificationRejections.WithLabelValues("other", "missing_required_field").Inc() + JobResult(provider, "invalid", 1) +} diff --git a/scraper-go/internal/metrics/maintenance.go b/scraper-go/internal/metrics/maintenance.go new file mode 100644 index 00000000..68f03e4e --- /dev/null +++ b/scraper-go/internal/metrics/maintenance.go @@ -0,0 +1,115 @@ +package metrics + +import ( + "context" + "math" + "strconv" + "sync" + "time" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" + "github.com/redis/go-redis/v9" +) + +var MaintenanceTelemetryAvailable = promauto.NewGauge(prometheus.GaugeOpts{Name: "candidate_scraper_maintenance_telemetry_available", Help: "Last bounded telemetry hash read succeeded"}) +var MaintenanceSampleTimestamp = promauto.NewGauge(prometheus.GaugeOpts{Name: "candidate_scraper_maintenance_sample_timestamp_seconds", Help: "Last successful maintenance telemetry sample"}) + +const MaintenanceMetricsKey = "scraper:observability:maintenance-metrics" + +var MaintenanceBuckets = []float64{.001, .01, .05, .1, .5, 1, 5, 30, 120, 600, 1800, 3600} +var maintenanceOperations = []string{"rebuild", "reconcile", "backfill", "reclassify", "expire", "rollback"} +var maintenanceStatuses = []string{"success", "failed", "canceled"} +var maintenanceData = struct { + sync.RWMutex + values map[string]string +}{values: map[string]string{}} + +type maintenanceCollector struct{} + +var maintenanceDurationDesc = prometheus.NewDesc("candidate_scraper_index_maintenance_duration_seconds", "Durable maintenance durations across CLI invocations", []string{"operation", "status"}, nil) +var maintenanceRunsDesc = prometheus.NewDesc("candidate_scraper_index_maintenance_runs_total", "Durable maintenance outcomes across CLI invocations", []string{"operation", "status"}, nil) +var cacheInvalidationDesc = prometheus.NewDesc("candidate_jobs_search_cache_invalidations_total", "Successful committed generation changes", []string{"reason"}, nil) +var reconciliationDesc = prometheus.NewDesc("candidate_scraper_index_reconciliation_total", "Durable explicit reconciliation outcomes", []string{"result"}, nil) + +func init() { prometheus.MustRegister(maintenanceCollector{}) } +func (maintenanceCollector) Describe(ch chan<- *prometheus.Desc) { + ch <- maintenanceDurationDesc + ch <- maintenanceRunsDesc + ch <- reconciliationDesc + ch <- cacheInvalidationDesc +} +func (maintenanceCollector) Collect(ch chan<- prometheus.Metric) { + maintenanceData.RLock() + defer maintenanceData.RUnlock() + v := maintenanceData.values + number := func(k string) float64 { + n, e := strconv.ParseFloat(v[k], 64) + if e != nil || n < 0 || math.IsNaN(n) || math.IsInf(n, 0) { + return 0 + } + return n + } + for _, op := range maintenanceOperations { + for _, status := range maintenanceStatuses { + p := op + ":" + status + ":" + count := uint64(number(p + "count")) + if count == 0 { + continue + } + buckets := map[float64]uint64{} + for _, b := range MaintenanceBuckets { + buckets[b] = uint64(number(p + strconv.FormatFloat(b, 'g', -1, 64))) + } + ch <- prometheus.MustNewConstHistogram(maintenanceDurationDesc, count, number(p+"sum"), buckets, op, status) + ch <- prometheus.MustNewConstMetric(maintenanceRunsDesc, prometheus.CounterValue, float64(count), op, status) + } + } + for _, reason := range []string{"job_created", "job_updated", "job_removed", "job_reclassified", "index_rebuilt", "taxonomy_changed"} { + ch <- prometheus.MustNewConstMetric(cacheInvalidationDesc, prometheus.CounterValue, number("cache:"+reason), reason) + } + for _, result := range []string{"consistent", "divergent", "failed", "canceled"} { + ch <- prometheus.MustNewConstMetric(reconciliationDesc, prometheus.CounterValue, number("reconcile:"+result), result) + } +} + +// No I/O in Collect. The bounded hash contains only fixed operations/statuses. +// A failed poll retains known cumulative values rather than resetting counters. +func StartMaintenanceSampler(parent context.Context, rdb *redis.Client) func() { + ctx, cancel := context.WithCancel(parent) + done := make(chan struct{}) + go func() { + defer close(done) + timer := time.NewTicker(15 * time.Second) + defer timer.Stop() + for { + pollCtx, stop := context.WithTimeout(ctx, 2*time.Second) + v, err := rdb.HGetAll(pollCtx, MaintenanceMetricsKey).Result() + stop() + if err == nil { + MaintenanceTelemetryAvailable.Set(1) + MaintenanceSampleTimestamp.Set(float64(time.Now().Unix())) + maintenanceData.Lock() + maintenanceData.values = v + maintenanceData.Unlock() + if n, e := strconv.ParseFloat(v["rebuildProgress"], 64); e == nil { + RebuildProgress.Set(n) + } + for _, k := range []string{"missing", "stale", "membership", "primary", "related", "any", "invalid", "documents", "counts"} { + if n, e := strconv.ParseFloat(v["divergence:"+k], 64); e == nil { + Divergences.WithLabelValues(k).Set(n) + } + } + } + if err != nil { + MaintenanceTelemetryAvailable.Set(0) + } + select { + case <-ctx.Done(): + return + case <-timer.C: + } + } + }() + return func() { cancel(); <-done } +} diff --git a/scraper-go/internal/metrics/operational.go b/scraper-go/internal/metrics/operational.go new file mode 100644 index 00000000..62ac54aa --- /dev/null +++ b/scraper-go/internal/metrics/operational.go @@ -0,0 +1,206 @@ +package metrics + +import ( + "context" + "errors" + "net" + "strings" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/ports" + "github.com/lib/pq" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" +) + +func counter(name string, labels ...string) *prometheus.CounterVec { + return promauto.NewCounterVec(prometheus.CounterOpts{Name: name, Help: strings.ReplaceAll(name, "_", " ")}, labels) +} +func gauge(name string, labels ...string) *prometheus.GaugeVec { + return promauto.NewGaugeVec(prometheus.GaugeOpts{Name: name, Help: strings.ReplaceAll(name, "_", " ")}, labels) +} +func histogram(name string, buckets []float64, labels ...string) *prometheus.HistogramVec { + return promauto.NewHistogramVec(prometheus.HistogramOpts{Name: name, Help: strings.ReplaceAll(name, "_", " "), Buckets: buckets}, labels) +} + +var durationBuckets = []float64{.001, .01, .05, .1, .5, 1, 5, 30, 120, 600, 1800, 3600} +var ( + Runs = counter("candidate_scraper_runs_total", "source", "status") + RunDuration = histogram("candidate_scraper_run_duration_seconds", durationBuckets, "source", "status") + LastRun = gauge("candidate_scraper_last_run_timestamp_seconds", "source", "status") + Progress = gauge("candidate_scraper_progress", "kind") + LastProgress = promauto.NewGauge(prometheus.GaugeOpts{Name: "candidate_scraper_last_progress_timestamp_seconds", Help: "Last real pipeline progress timestamp"}) + ProviderConfigured = gauge("candidate_scraper_provider_configured_concurrency", "provider") + ProviderActive = gauge("candidate_scraper_provider_active_tasks", "provider") + ProviderWaiting = gauge("candidate_scraper_provider_waiting_tasks", "provider") + ProviderRuns = counter("candidate_scraper_provider_runs_total", "provider", "status") + ProviderDuration = histogram("candidate_scraper_provider_duration_seconds", durationBuckets, "provider", "status") + ProviderErrors = counter("candidate_scraper_provider_errors_total", "provider", "error_type") + ProviderTimeouts = counter("candidate_scraper_provider_timeouts_total", "provider") + ProviderJobs = counter("candidate_scraper_provider_jobs_total", "provider", "result") + DiscoveryRuns = counter("candidate_scraper_provider_discovery_runs_total", "provider", "mode") + DiscoveryKeywords = counter("candidate_scraper_provider_keywords_total", "provider", "mode") + LockConflicts = counter("candidate_scraper_lock_conflicts_total", "source") + LockRenewFailures = promauto.NewCounter(prometheus.CounterOpts{Name: "candidate_scraper_lock_renew_failures_total", Help: "Temporary renewal failures"}) + LockLost = counter("candidate_scraper_lock_lost_total", "source") + ClassificationJobs = counter("candidate_scraper_classification_jobs_total", "result", "family") + ClassificationDuration = histogram("candidate_scraper_classification_duration_seconds", durationBuckets, "result") + ClassificationRejections = counter("candidate_scraper_classification_rejections_total", "family", "reason_code") + PersistenceDuration = histogram("candidate_scraper_persistence_batch_duration_seconds", durationBuckets, "status") + PersistenceBatches = counter("candidate_scraper_persistence_batches_total", "status") + PersistenceJobs = counter("candidate_scraper_persistence_jobs_total", "result") + PersistenceRetries = counter("candidate_scraper_persistence_retries_total", "reason") + PersistenceRollbacks = counter("candidate_scraper_persistence_rollbacks_total", "reason") + PersistenceFailures = counter("candidate_scraper_persistence_failures_total", "reason") + PersistenceBatchSize = histogram("candidate_scraper_persistence_batch_size", []float64{1, 10, 50, 100, 200, 500, 1000, 2500}) + CacheInvalidationDuration = histogram("candidate_jobs_search_cache_operation_duration_seconds", durationBuckets, "operation") + IndexDuration = histogram("candidate_scraper_index_batch_duration_seconds", durationBuckets, "status") + IndexBatches = counter("candidate_scraper_index_batches_total", "status") + IndexJobs = counter("candidate_scraper_index_jobs_total", "result") + IndexFailures = counter("candidate_scraper_index_failures_total", "reason") + IndexBatchSize = histogram("candidate_scraper_index_batch_size", []float64{1, 10, 50, 100, 200, 500, 1000, 2500}) + Divergences = gauge("candidate_scraper_index_reconciliation_divergences", "kind") + RebuildProgress = promauto.NewGauge(prometheus.GaugeOpts{Name: "candidate_scraper_index_rebuild_jobs", Help: "Jobs projected by current or last rebuild"}) + // Defined in both owners with exactly the same schema. Aggregate by job in rules + // when attribution is required; Go observes only committed projection changes. +) + +func Source(source string) string { + if source == "cron" { + return "cron" + } + return "manual" +} +func Provider(value string) string { + if p, ok := ports.ParseProviderID(strings.ReplaceAll(strings.Split(strings.ToLower(strings.TrimSpace(value)), ":")[0], " ", "")); ok { + return string(p) + } + return "unknown" +} +func ErrorType(err error) string { + if err == nil { + return "none" + } + if errors.Is(err, context.DeadlineExceeded) { + return "timeout" + } + if errors.Is(err, context.Canceled) { + return "canceled" + } + var e net.Error + if errors.As(err, &e) { + if e.Timeout() { + return "timeout" + } + return "network" + } + // Legacy adapters expose status through wrapped strings. Only fixed categories + // escape this boundary; the actual message is never a metric label. + s := strings.ToLower(err.Error()) + if strings.Contains(s, "scraper run lock lost") { + return "canceled" + } + switch { + case strings.Contains(s, "429") || strings.Contains(s, "rate limit"): + return "rate_limit" + case strings.Contains(s, "401") || strings.Contains(s, "403"): + return "authentication" + case strings.Contains(s, "timeout") || strings.Contains(s, "deadline"): + return "timeout" + case strings.Contains(s, "decode") || strings.Contains(s, "unmarshal") || strings.Contains(s, "json"): + return "parsing" + case strings.Contains(s, "invalid") || strings.Contains(s, "validation"): + return "validation" + case strings.Contains(s, "connection") || strings.Contains(s, "network"): + return "network" + } + return "unknown" +} +func Status(err error) string { + if err == nil { + return "success" + } + t := ErrorType(err) + if t == "timeout" || t == "canceled" { + return t + } + return "failed" +} +func BatchStatus(err error) string { + s := Status(err) + if s == "timeout" { + return "canceled" + } + return s +} +func RecordProvider(provider, mode string, keywords, jobs int, started time.Time, err error) { + p := Provider(provider) + status := Status(err) + ProviderRuns.WithLabelValues(p, status).Inc() + ProviderDuration.WithLabelValues(p, status).Observe(time.Since(started).Seconds()) + DiscoveryRuns.WithLabelValues(p, mode).Inc() + DiscoveryKeywords.WithLabelValues(p, mode).Add(float64(keywords)) + if err != nil { + ProviderErrors.WithLabelValues(p, ErrorType(err)).Inc() + if status == "timeout" { + ProviderTimeouts.WithLabelValues(p).Inc() + } + } + ProviderJobs.WithLabelValues(p, "collected").Add(float64(jobs)) + taskFinished(p, status, keywords) +} +func JobResult(provider, result string, n int) { + if n > 0 { + seen := map[string]bool{} + for _, source := range strings.Split(provider, ",") { + p := Provider(source) + if !seen[p] { + ProviderJobs.WithLabelValues(p, result).Add(float64(n)) + seen[p] = true + } + } + } +} +func ObservePersistence(started time.Time, size, inserted, updated, skipped int, err error) { + status := BatchStatus(err) + PersistenceDuration.WithLabelValues(status).Observe(time.Since(started).Seconds()) + PersistenceBatches.WithLabelValues(status).Inc() + PersistenceBatchSize.WithLabelValues().Observe(float64(size)) + if err != nil { + RecordStateError(err) + PersistenceJobs.WithLabelValues("failed").Add(float64(size)) + PersistenceFailures.WithLabelValues(PersistenceErrorReason(err)).Inc() + } else { + PersistenceJobs.WithLabelValues("inserted").Add(float64(inserted)) + PersistenceJobs.WithLabelValues("updated").Add(float64(updated)) + PersistenceJobs.WithLabelValues("skipped").Add(float64(max(0, skipped))) + } +} +func ObserveIndex(started time.Time, size, changed int, err error) { + status := BatchStatus(err) + IndexDuration.WithLabelValues(status).Observe(time.Since(started).Seconds()) + IndexBatches.WithLabelValues(status).Inc() + IndexBatchSize.WithLabelValues().Observe(float64(size)) + if err != nil { + RecordStateError(err) + IndexFailures.WithLabelValues(ErrorType(err)).Inc() + IndexJobs.WithLabelValues("failed").Add(float64(size)) + } else { + IndexJobs.WithLabelValues("updated").Add(float64(changed)) + IndexJobs.WithLabelValues("skipped").Add(float64(max(0, size-changed))) + } +} + +func PersistenceErrorReason(err error) string { + var e *pq.Error + if errors.As(err, &e) { + if e.Code == "40001" || e.Code == "40P01" || e.Code == "23505" { + return "conflict" + } + if strings.HasPrefix(string(e.Code), "08") { + return "network" + } + return "permanent" + } + return ErrorType(err) +} diff --git a/scraper-go/internal/metrics/operational_test.go b/scraper-go/internal/metrics/operational_test.go new file mode 100644 index 00000000..5f2811fc --- /dev/null +++ b/scraper-go/internal/metrics/operational_test.go @@ -0,0 +1,195 @@ +package metrics + +import ( + "context" + "errors" + "fmt" + "strings" + "testing" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/ports" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" +) + +func TestExecutionOutcomesAndState(t *testing.T) { + for _, source := range []string{"cron", "admin_manual", "public_endpoint"} { + for _, test := range []struct { + err error + status string + }{{nil, "success"}, {errors.New("failure"), "failed"}, {context.Canceled, "canceled"}, {context.DeadlineExceeded, "timeout"}} { + before := testutil.ToFloat64(Runs.WithLabelValues(Source(source), test.status)) + StartRun(source, time.Now().Add(-time.Second)) + if Current().Execution.Status != "running" { + t.Fatal("run not active") + } + FinishRun(test.err) + s := Current() + if s.Execution.LastStatus == nil || *s.Execution.LastStatus != test.status || s.Execution.LastDurationSeconds < 1 || s.Execution.FinishedAt == nil { + t.Fatalf("bad last run: %+v", s.Execution) + } + if got := testutil.ToFloat64(Runs.WithLabelValues(Source(source), test.status)); got != before+1 { + t.Fatal("run counted incorrectly") + } + } + } + before := testutil.ToFloat64(Runs.WithLabelValues("cron", "skipped")) + Attempt("cron", "skipped") + if testutil.ToFloat64(Runs.WithLabelValues("cron", "skipped")) != before+1 { + t.Fatal("skip missing") + } + StartRun("cron", time.Now()) + Canceling() + if Current().Execution.Status != "canceling" { + t.Fatal("cancellation missing") + } + FinishRun(context.Canceled) +} +func TestConcurrencyQueuesAndLock(t *testing.T) { + StartRun("manual", time.Now()) + Configure(12, 8, nil, 0, func(ports.ProviderID) int { return 2 }) + Active("linkedin", 1) + Waiting("linkedin", 1) + BindQueue("collection", func() Queue { return Queue{2, 4} }) + s := Current() + if s.Concurrency.Configured != 12 || s.Concurrency.Effective != 8 || s.Concurrency.Active != 1 || s.Concurrency.Waiting != 1 || s.Queues["collection"].Depth != 2 { + t.Fatalf("wrong concurrency %+v", s) + } + Active("linkedin", -1) + Active("linkedin", -1) + Waiting("linkedin", -1) + Waiting("linkedin", -1) + if Current().Concurrency.Active < 0 || Current().Concurrency.Waiting < 0 { + t.Fatal("negative gauge") + } + Active("linkedin", 1) + Waiting("linkedin", 1) + ClearQueues() + if Current().Concurrency.Active != 0 || Current().Concurrency.Waiting != 0 || testutil.ToFloat64(ProviderWaiting.WithLabelValues("linkedin")) != 0 { + t.Fatal("canceled pipeline left tasks waiting") + } + LockAcquired(time.Second) + if !Current().Lock.Held || Current().Lock.TTLSeconds < 0 { + t.Fatal("lock state") + } + LockReleased() + if Current().Lock.Held || Current().Lock.TTLSeconds != 0 { + t.Fatal("lock release") + } + FinishRun(nil) + if Current().Queues["collection"].Depth != 0 || Current().Concurrency.Active != 0 || Current().Concurrency.Waiting != 0 { + t.Fatal("unfinished live state") + } +} +func TestProviderAndErrorCategories(t *testing.T) { + for _, tt := range []struct { + err error + category string + }{{context.Canceled, "canceled"}, {context.DeadlineExceeded, "timeout"}, {errors.New("HTTP 429 secret"), "rate_limit"}, {errors.New("HTTP 401"), "authentication"}, {errors.New("json decode private"), "parsing"}, {errors.New("invalid"), "validation"}, {errors.New("network connection"), "network"}, {errors.New("sensitive arbitrary failure"), "unknown"}} { + if ErrorType(tt.err) != tt.category { + t.Fatal(tt) + } + } + for _, mode := range []string{"keyword", "batch", "catalog"} { + RecordProvider("greenhouse", mode, 3, 2, time.Now(), nil) + } + if Provider("Green House:some private company") != "greenhouse" || Provider("arbitrary company") != "unknown" { + t.Fatal("provider label unbounded") + } + before := testutil.ToFloat64(ProviderJobs.WithLabelValues("linkedin", "persisted")) + JobResult("LinkedIn, Gupy, LinkedIn", "persisted", 1) + if testutil.ToFloat64(ProviderJobs.WithLabelValues("linkedin", "persisted")) != before+1 { + t.Fatal("merged providers were not deduplicated") + } +} +func TestClassificationRejectionsAndBoundedTitles(t *testing.T) { + StartRun("manual", time.Now()) + for _, family := range []string{"product", "product_design"} { + Classification(domain.Job{Title: "private title", Source: "linkedin"}, domain.Classification{PrimaryFamily: family, InScope: true}, time.Now()) + if testutil.ToFloat64(ClassificationJobs.WithLabelValues("approved", family)) == 0 { + t.Fatal("missing product") + } + } + Classification(domain.Job{Title: "Production Manager"}, domain.Classification{PrimaryFamily: "other", Reasons: []string{"vaga administrativa: produto"}}, time.Now()) + Classification(domain.Job{Title: "Unrecognized"}, domain.Classification{PrimaryFamily: "other", Reasons: []string{"nenhuma familia reconhecida"}}, time.Now()) + InvalidJob("unknown") + for i := 0; i < 1000; i++ { + RejectTitle(fmt.Sprintf("Title %d", i), "negative_title") + } + s := Current() + if len(s.RejectedTitles) > 10 || len(state.titles) > 100 { + t.Fatal("unbounded title aggregate") + } + FinishRun(nil) +} +func TestMetricLabelCardinalityPolicy(t *testing.T) { + // Exercise arbitrary IDs/text first, then inspect actual registered series. + RecordProvider("url/user-secret", "keyword", 2, 0, time.Now(), errors.New("job-id secret error")) + allowedNames := map[string]bool{"adapter": true, "provider": true, "source": true, "status": true, "result": true, "mode": true, "family": true, "reason_code": true, "error_type": true, "reason": true, "kind": true, "queue": true, "operation": true} + allowedValues := map[string]bool{} + for _, s := range strings.Fields("linkedin adzuna themuse gupy inhire jooble greenhouse lever unknown manual cron success failed canceled skipped timeout approved rejected other invalid collected valid duplicate persisted indexed keyword batch catalog backend frontend fullstack mobile data devops platform qa security product product_design software leadership no_family_recognized negative_title insufficient_title_evidence missing_required_field classification_error network rate_limit authentication parsing validation persistence indexing inserted updated no_family_recognized collection classification tasksTotal tasksCompleted tasksCanceled providersTotal providersCompleted adaptersTotal adaptersProcessed keywordsTotal keywordsProcessed batchesCompleted missing stale membership primary related any documents counts job_created job_updated job_removed job_reclassified index_rebuilt taxonomy_changed invalidate conflict permanent consistent divergent rebuild reconcile backfill reclassify expire rollback") { + allowedValues[s] = true + } + all, err := prometheus.DefaultGatherer.Gather() + if err != nil { + t.Fatal(err) + } + for _, family := range all { + if !strings.HasPrefix(family.GetName(), "candidate_") && !strings.HasPrefix(family.GetName(), "scraper_") { + continue + } + for _, m := range family.Metric { + for _, l := range m.Label { + if !allowedNames[l.GetName()] || !allowedValues[l.GetValue()] { + t.Fatalf("uncontrolled metric label %s %s=%q", family.GetName(), l.GetName(), l.GetValue()) + } + } + } + } +} + +func TestOldLeaseCannotResetCurrentState(t *testing.T) { + StartRun("manual", time.Now(), "old") + LockAcquired(time.Minute, "old") + StartRun("cron", time.Now(), "new") + LockAcquired(time.Minute, "new") + LockReleased("old") + FinishRun(context.Canceled, "old") + if !Current().Lock.Held || Current().Execution.Status != "running" || *Current().Execution.Source != "cron" { + t.Fatal("old lease changed new run") + } + LockReleased("new") + FinishRun(nil, "new") +} +func TestPersistenceAndIndexOutcomes(t *testing.T) { + for _, err := range []error{nil, errors.New("permanent failure"), context.Canceled} { + before := testutil.ToFloat64(PersistenceBatches.WithLabelValues(BatchStatus(err))) + ObservePersistence(time.Now(), 4, 1, 2, 1, err) + if testutil.ToFloat64(PersistenceBatches.WithLabelValues(BatchStatus(err))) != before+1 { + t.Fatal("persistence result missing") + } + before = testutil.ToFloat64(IndexBatches.WithLabelValues(BatchStatus(err))) + ObserveIndex(time.Now(), 4, 3, err) + if testutil.ToFloat64(IndexBatches.WithLabelValues(BatchStatus(err))) != before+1 { + t.Fatal("index result missing") + } + } +} + +func TestRuntimeMetricsAreReused(t *testing.T) { + families, err := prometheus.DefaultGatherer.Gather() + if err != nil { + t.Fatal(err) + } + names := map[string]bool{} + for _, f := range families { + names[f.GetName()] = true + } + for _, name := range []string{"go_goroutines", "go_memstats_heap_alloc_bytes", "go_gc_duration_seconds", "go_sched_gomaxprocs_threads", "go_gc_gomemlimit_bytes", "process_cpu_seconds_total", "process_resident_memory_bytes"} { + if !names[name] { + t.Fatalf("missing reused runtime metric %s", name) + } + } +} diff --git a/scraper-go/internal/metrics/state.go b/scraper-go/internal/metrics/state.go new file mode 100644 index 00000000..623a9dfd --- /dev/null +++ b/scraper-go/internal/metrics/state.go @@ -0,0 +1,475 @@ +package metrics + +import ( + "runtime" + runtimemetrics "runtime/metrics" + "sort" + "strings" + "sync" + "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/ports" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/taxonomy" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promauto" +) + +type Execution struct { + Status string `json:"status"` + Source *string `json:"source"` + StartedAt *time.Time `json:"startedAt"` + DurationSeconds float64 `json:"durationSeconds"` + FinishedAt *time.Time `json:"finishedAt"` + LastDurationSeconds float64 `json:"lastDurationSeconds"` + LastStatus *string `json:"lastStatus"` + NextRunAt *time.Time `json:"nextRunAt"` + Stage *string `json:"stage"` + ApplicationVersion string `json:"applicationVersion"` + TaxonomyVersion string `json:"taxonomyVersion"` +} +type Concurrency struct { + Configured int `json:"configured"` + Effective int `json:"effective"` + Active int `json:"active"` + Waiting int `json:"waiting"` +} +type Lock struct { + Held bool `json:"held"` + TTLSeconds float64 `json:"ttlSeconds"` +} +type Queue struct { + Depth int `json:"depth"` + Capacity int `json:"capacity"` +} +type RejectedTitle struct { + Title string `json:"title"` + Count int `json:"count"` + ReasonCode string `json:"reasonCode"` +} +type MaintenanceSummary struct { + Operation string `json:"operation"` + Status string `json:"status"` + DurationSeconds float64 `json:"durationSeconds"` + FinishedAt time.Time `json:"finishedAt"` + Processed int `json:"processed"` + Divergences int `json:"divergences"` +} + +func (s MaintenanceSummary) Valid() bool { + switch s.Operation { + case "rebuild", "reconcile", "backfill", "reclassify", "expire", "rollback": + default: + return false + } + return (s.Status == "success" || s.Status == "failed" || s.Status == "canceled") && + s.DurationSeconds >= 0 && s.Processed >= 0 && s.Divergences >= 0 && !s.FinishedAt.IsZero() +} + +type Snapshot struct { + Execution Execution `json:"execution"` + Lock Lock `json:"lock"` + Concurrency Concurrency `json:"concurrency"` + Progress map[string]int `json:"progress"` + Queues map[string]Queue `json:"queues"` + Errors struct { + Total int `json:"total"` + Timeouts int `json:"timeouts"` + } `json:"errors"` + RejectedTitles []RejectedTitle `json:"rejectedTitles"` + RejectedTitlesSince time.Time `json:"rejectedTitlesSince"` +} + +var state = struct { + sync.Mutex + runID string + lockRunID string + execution Execution + concurrency Concurrency + expiry time.Time + held bool + progress map[string]int + providerRemaining map[string]int + adapterRemaining map[int]int + active, waiting map[string]int + queues map[string]func() Queue + errors, timeouts int + titles map[string]RejectedTitle + titlesSince time.Time +}{execution: Execution{Status: "idle", ApplicationVersion: "unknown", TaxonomyVersion: taxonomy.Version()}, progress: map[string]int{}, providerRemaining: map[string]int{}, adapterRemaining: map[int]int{}, active: map[string]int{}, waiting: map[string]int{}, queues: map[string]func() Queue{}, titles: map[string]RejectedTitle{}, titlesSince: time.Now().UTC()} +var progressKinds = []string{"providersTotal", "providersCompleted", "adaptersTotal", "adaptersProcessed", "tasksTotal", "tasksCompleted", "tasksCanceled", "keywordsTotal", "keywordsProcessed", "batchesCompleted"} +var CronInterval = promauto.NewGauge(prometheus.GaugeOpts{Name: "candidate_scraper_cron_interval_seconds", Help: "Configured cron interval"}) + +var queueNames = []string{"collection", "classification", "persistence", "indexing"} + +func init() { + for _, item := range []struct { + name string + get func() float64 + }{ + {"candidate_scraper_configured_concurrency", func() float64 { return float64(Current().Concurrency.Configured) }}, + {"candidate_scraper_effective_concurrency", func() float64 { return float64(Current().Concurrency.Effective) }}, + {"candidate_scraper_active_tasks", func() float64 { return float64(Current().Concurrency.Active) }}, + {"candidate_scraper_waiting_tasks", func() float64 { return float64(Current().Concurrency.Waiting) }}, + {"candidate_scraper_lock_held", func() float64 { + if Current().Lock.Held { + return 1 + } + return 0 + }}, + {"candidate_scraper_lock_ttl_seconds", func() float64 { return Current().Lock.TTLSeconds }}, + {"candidate_scraper_run_started_timestamp_seconds", func() float64 { + v := Current().Execution.StartedAt + if v == nil { + return 0 + } + return float64(v.Unix()) + }}, + {"candidate_scraper_running", func() float64 { + s := Current().Execution.Status + if s == "running" || s == "canceling" { + return 1 + } + return 0 + }}, + } { + promauto.NewGaugeFunc(prometheus.GaugeOpts{Name: item.name, Help: item.name}, item.get) + } + for _, q := range queueNames { + for _, kind := range []string{"depth", "capacity"} { + promauto.NewGaugeFunc(prometheus.GaugeOpts{Name: "candidate_scraper_queue_" + kind, Help: "Actual bounded queue " + kind, ConstLabels: prometheus.Labels{"queue": q}}, func() float64 { + v := Current().Queues[q] + if kind == "capacity" { + return float64(v.Capacity) + } + return float64(v.Depth) + }) + } + } + // These settings are already exposed by the default Go collector. Do not + // create duplicate runtime/resource metrics here. +} +func SetVersion(version string) { + state.Lock() + defer state.Unlock() + state.execution.ApplicationVersion = version +} +func SetNextRun(t time.Time) { + state.Lock() + defer state.Unlock() + if t.IsZero() { + state.execution.NextRunAt = nil + } else { + state.execution.NextRunAt = &t + } +} +func StartRun(source string, started time.Time, runID ...string) { + state.Lock() + defer state.Unlock() + state.runID = "" + if len(runID) > 0 { + state.runID = runID[0] + } + s := Source(source) + state.execution.Status = "running" + state.execution.Source = &s + state.execution.StartedAt = &started + stage := "collection" + state.execution.Stage = &stage + state.progress = map[string]int{} + for _, k := range progressKinds { + state.progress[k] = 0 + Progress.WithLabelValues(k).Set(0) + } + state.errors = 0 + state.timeouts = 0 + state.titles = map[string]RejectedTitle{} + state.titlesSince = started + LastProgress.Set(float64(started.Unix())) +} +func FinishRun(err error, runID ...string) { + state.Lock() + defer state.Unlock() + if len(runID) > 0 && runID[0] != state.runID { + return + } + if state.execution.StartedAt == nil || state.execution.Source == nil { + return + } + status := Status(err) + now := time.Now().UTC() + duration := now.Sub(*state.execution.StartedAt).Seconds() + source := *state.execution.Source + Runs.WithLabelValues(source, status).Inc() + RunDuration.WithLabelValues(source, status).Observe(duration) + LastRun.WithLabelValues(source, status).Set(float64(now.Unix())) + state.execution.FinishedAt = &now + state.execution.LastDurationSeconds = duration + state.execution.LastStatus = &status + if err == nil { + state.execution.Status = "completed" + } else { + state.execution.Status = "failed" + } + state.execution.Stage = nil + if status == "canceled" || status == "timeout" { + n := max(0, state.progress["tasksTotal"]-state.progress["tasksCompleted"]) + state.progress["tasksCanceled"] += n + Progress.WithLabelValues("tasksCanceled").Set(float64(state.progress["tasksCanceled"])) + } + state.concurrency.Active = 0 + state.concurrency.Waiting = 0 + state.active = map[string]int{} + state.waiting = map[string]int{} + for p := range state.providerRemaining { + ProviderActive.WithLabelValues(p).Set(0) + ProviderWaiting.WithLabelValues(p).Set(0) + } + state.queues = map[string]func() Queue{} +} +func Attempt(source, status string) { + source = Source(source) + Runs.WithLabelValues(source, status).Inc() + RunDuration.WithLabelValues(source, status).Observe(0) + LastRun.WithLabelValues(source, status).Set(float64(time.Now().Unix())) +} +func Canceling(runID ...string) { + state.Lock() + defer state.Unlock() + if len(runID) > 0 && runID[0] != state.runID { + return + } + if state.execution.Status == "running" { + state.execution.Status = "canceling" + } +} +func LockAcquired(ttl time.Duration, runID ...string) { + state.Lock() + defer state.Unlock() + if len(runID) > 0 { + state.lockRunID = runID[0] + } + state.held = true + state.expiry = time.Now().Add(ttl) +} +func LockReleased(runID ...string) { + state.Lock() + defer state.Unlock() + if len(runID) > 0 && runID[0] != state.lockRunID { + return + } + state.held = false + state.expiry = time.Time{} +} +func Stage(stage string) { state.Lock(); defer state.Unlock(); state.execution.Stage = &stage } +func BindQueue(name string, read func() Queue) { + state.Lock() + defer state.Unlock() + state.queues[name] = read +} +func ClearQueues() { + state.Lock() + defer state.Unlock() + state.queues = map[string]func() Queue{} + state.concurrency.Active = 0 + state.concurrency.Waiting = 0 + for p := range state.active { + ProviderActive.WithLabelValues(p).Set(0) + } + for p := range state.waiting { + ProviderWaiting.WithLabelValues(p).Set(0) + } + state.active = map[string]int{} + state.waiting = map[string]int{} +} +func AddProgress(kind string, n int) { state.Lock(); defer state.Unlock(); addProgress(kind, n) } +func addProgress(kind string, n int) { + state.progress[kind] += n + Progress.WithLabelValues(kind).Set(float64(state.progress[kind])) + LastProgress.Set(float64(time.Now().Unix())) +} +func Configure(configured, effective int, sources []ports.JobSource, keywords int, limit func(ports.ProviderID) int) { + state.Lock() + defer state.Unlock() + if configured > 0 { + state.concurrency.Configured = configured + } + state.concurrency.Effective = effective + state.providerRemaining = map[string]int{} + state.adapterRemaining = map[int]int{} + ProviderConfigured.Reset() + tasks := 0 + for i, a := range sources { + c := ports.CapabilitiesOf(a) + n := 1 + if c.Mode == ports.DiscoveryKeyword { + n = keywords + } + p := Provider(string(c.Provider)) + state.providerRemaining[p] += n + state.adapterRemaining[i] = n + tasks += n + ProviderConfigured.WithLabelValues(p).Set(float64(limit(c.Provider))) + ProviderActive.WithLabelValues(p).Set(0) + ProviderWaiting.WithLabelValues(p).Set(0) + } + state.progress["providersTotal"] = len(state.providerRemaining) + state.progress["adaptersTotal"] = len(sources) + state.progress["tasksTotal"] = tasks + // KeywordsProcessed counts the actual keyword inputs consumed across tasks, + // not distinct strings (strings are never stored for metrics). + state.progress["keywordsTotal"] = 0 + for i, a := range sources { + c := ports.CapabilitiesOf(a) + n := state.adapterRemaining[i] + if c.Mode == ports.DiscoveryKeyword { + state.progress["keywordsTotal"] += n + } else { + state.progress["keywordsTotal"] += keywords + } + } + for k, v := range state.progress { + Progress.WithLabelValues(k).Set(float64(v)) + } +} +func Waiting(provider string, delta int) { + p := Provider(provider) + state.Lock() + defer state.Unlock() + state.waiting[p] = max(0, state.waiting[p]+delta) + state.concurrency.Waiting = max(0, state.concurrency.Waiting+delta) + ProviderWaiting.WithLabelValues(p).Set(float64(state.waiting[p])) +} +func Active(provider string, delta int) { + p := Provider(provider) + state.Lock() + defer state.Unlock() + state.active[p] = max(0, state.active[p]+delta) + state.concurrency.Active = max(0, state.concurrency.Active+delta) + ProviderActive.WithLabelValues(p).Set(float64(state.active[p])) +} +func AdapterFinished(adapter int) { + state.Lock() + defer state.Unlock() + if n := state.adapterRemaining[adapter]; n > 0 { + state.adapterRemaining[adapter] = n - 1 + if n == 1 { + addProgress("adaptersProcessed", 1) + } + } +} +func taskFinished(provider, status string, keywords int) { + state.Lock() + defer state.Unlock() + addProgress("tasksCompleted", 1) + addProgress("keywordsProcessed", keywords) + if status == "canceled" || status == "timeout" { + addProgress("tasksCanceled", 1) + } + if status != "success" { + state.errors++ + if status == "timeout" { + state.timeouts++ + } + } + if n := state.providerRemaining[provider]; n > 0 { + state.providerRemaining[provider] = n - 1 + if n == 1 { + addProgress("providersCompleted", 1) + } + } +} +func Current() Snapshot { + state.Lock() + defer state.Unlock() + s := Snapshot{Execution: state.execution, Concurrency: state.concurrency, Lock: Lock{Held: state.held, TTLSeconds: max(0, time.Until(state.expiry).Seconds())}, Progress: map[string]int{}, Queues: map[string]Queue{}, RejectedTitles: []RejectedTitle{}, RejectedTitlesSince: state.titlesSince} + if s.Execution.StartedAt != nil { + if s.Execution.Status == "running" || s.Execution.Status == "canceling" { + s.Execution.DurationSeconds = max(0, time.Since(*s.Execution.StartedAt).Seconds()) + } else { + s.Execution.DurationSeconds = s.Execution.LastDurationSeconds + } + } + for k, v := range state.progress { + s.Progress[k] = v + } + for _, k := range progressKinds { + if _, ok := s.Progress[k]; !ok { + s.Progress[k] = 0 + } + } + for _, q := range queueNames { + if f := state.queues[q]; f != nil { + s.Queues[q] = f() + } else { + s.Queues[q] = Queue{} + } + } + s.Errors.Total = state.errors + s.Errors.Timeouts = state.timeouts + if time.Since(state.titlesSince) < 24*time.Hour { + for _, v := range state.titles { + s.RejectedTitles = append(s.RejectedTitles, v) + } + } + sort.Slice(s.RejectedTitles, func(i, j int) bool { + a, b := s.RejectedTitles[i], s.RejectedTitles[j] + if a.Count != b.Count { + return a.Count > b.Count + } + if a.Title != b.Title { + return a.Title < b.Title + } + return a.ReasonCode < b.ReasonCode + }) + if len(s.RejectedTitles) > 10 { + s.RejectedTitles = s.RejectedTitles[:10] + } + return s +} +func RejectTitle(title, reason string) { + state.Lock() + defer state.Unlock() + if time.Since(state.titlesSince) >= 24*time.Hour { + state.titles = map[string]RejectedTitle{} + state.titlesSince = time.Now().UTC() + } + r := []rune(stringsLowerSpace(title)) + if len(r) > 50 { + r = r[:50] + } + t := string(r) + if t == "" || strings.Contains(t, "@") || strings.Contains(t, "http://") || strings.Contains(t, "https://") { + return + } + key := reason + ":" + t + if _, ok := state.titles[key]; !ok && len(state.titles) >= 100 { + return + } + v := state.titles[key] + v.Title = t + v.ReasonCode = reason + v.Count++ + state.titles[key] = v +} +func RuntimeSettings() (int, int64) { + samples := []runtimemetrics.Sample{{Name: "/gc/gomemlimit:bytes"}} + runtimemetrics.Read(samples) + return runtime.GOMAXPROCS(0), int64(samples[0].Value.Uint64()) +} + +func stringsLowerSpace(s string) string { return strings.ToLower(strings.Join(strings.Fields(s), " ")) } + +func SetConfiguredConcurrency(n int) { + state.Lock() + defer state.Unlock() + state.concurrency.Configured = n +} + +func RecordStateError(err error) { + state.Lock() + defer state.Unlock() + state.errors++ + if ErrorType(err) == "timeout" { + state.timeouts++ + } +} diff --git a/scraper-go/internal/pipeline/budget.go b/scraper-go/internal/pipeline/budget.go index 253ada60..ccf937f3 100644 --- a/scraper-go/internal/pipeline/budget.go +++ b/scraper-go/internal/pipeline/budget.go @@ -5,6 +5,7 @@ import ( "fmt" "sync" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/ports" ) @@ -55,6 +56,8 @@ func (b *concurrencyBudget) acquire( return nil, cause } + metrics.Waiting(string(provider), 1) + defer metrics.Waiting(string(provider), -1) providerSemaphore := b.providerSemaphore(provider) select { case providerSemaphore <- struct{}{}: @@ -70,8 +73,10 @@ func (b *concurrencyBudget) acquire( case b.global <- struct{}{}: permit := &concurrencyPermit{ budget: b, + provider: provider, providerSemaphore: providerSemaphore, } + metrics.Active(string(provider), 1) if cause := context.Cause(ctx); cause != nil { permit.release() return nil, cause @@ -112,6 +117,7 @@ func (b *concurrencyBudget) providerInUse(provider ports.ProviderID) int { } type concurrencyPermit struct { + provider ports.ProviderID once sync.Once budget *concurrencyBudget providerSemaphore chan struct{} @@ -122,6 +128,7 @@ func (p *concurrencyPermit) release() { return } p.once.Do(func() { + metrics.Active(string(p.provider), -1) <-p.budget.global <-p.providerSemaphore }) diff --git a/scraper-go/internal/pipeline/pipeline.go b/scraper-go/internal/pipeline/pipeline.go index a7e31bc2..c61fe880 100644 --- a/scraper-go/internal/pipeline/pipeline.go +++ b/scraper-go/internal/pipeline/pipeline.go @@ -26,6 +26,7 @@ type result struct { } type adapterTask struct { + ordinal int adapter ports.JobSource provider ports.ProviderID mode ports.DiscoveryMode @@ -69,6 +70,10 @@ func runWithConcurrency( results := make(chan result, queueCapacity) incoming := make(chan domain.Job, stageQueueCapacity(processCfg)) runStats := newProviderRunStats(adapterList, budget) + metrics.Configure(0, maxConcurrency, adapterList, len(req.Keywords), budget.providerLimit) + metrics.BindQueue("collection", func() metrics.Queue { return metrics.Queue{Depth: len(tasks), Capacity: cap(tasks)} }) + metrics.BindQueue("classification", func() metrics.Queue { return metrics.Queue{Depth: len(incoming), Capacity: cap(incoming)} }) + defer metrics.ClearQueues() var tasksWg sync.WaitGroup tasksWg.Add(1 + maxConcurrency) @@ -139,6 +144,7 @@ func runWithConcurrency( } type taskCursor struct { + ordinal int adapter ports.JobSource provider ports.ProviderID mode ports.DiscoveryMode @@ -162,9 +168,10 @@ func produceTasks( providerIndexes := make(map[ports.ProviderID]int) cursors := make([]providerTaskCursor, 0, len(adapterList)) - for _, adapter := range adapterList { + for ordinal, adapter := range adapterList { capabilities := ports.CapabilitiesOf(adapter) sourceCursor := taskCursor{ + ordinal: ordinal, adapter: adapter, provider: capabilities.Provider, mode: capabilities.Mode, @@ -189,10 +196,12 @@ func produceTasks( if cause := context.Cause(ctx); cause != nil { return } + metrics.Waiting(string(task.provider), 1) select { case queue <- task: runStats.recordProduced(task) case <-ctx.Done(): + metrics.Waiting(string(task.provider), -1) return } } @@ -225,6 +234,7 @@ func (c *taskCursor) nextTask(keywords []string) (adapterTask, bool) { c.emitted = true return adapterTask{ adapter: c.adapter, + ordinal: c.ordinal, provider: c.provider, mode: c.mode, keywords: append([]string(nil), keywords...), @@ -236,6 +246,7 @@ func (c *taskCursor) nextTask(keywords []string) (adapterTask, bool) { } task := adapterTask{ adapter: c.adapter, + ordinal: c.ordinal, provider: c.provider, mode: c.mode, keywords: []string{keywords[c.next]}, @@ -304,6 +315,7 @@ func runWorker( if !ok { return } + metrics.Waiting(string(task.provider), -1) if context.Cause(ctx) != nil { return } @@ -326,12 +338,18 @@ func runScheduledTask( } defer permit.release() - source := string(task.provider) + source := metrics.Provider(string(task.provider)) started := time.Now() timer := prometheus.NewTimer(metrics.ScrapeDurationSeconds.WithLabelValues(source)) jobs, err := runAdapterTask(ctx, task, req) timer.ObserveDuration() runStats.recordCompleted(ctx, task, err, time.Since(started)) + observedErr := err + if cause := context.Cause(ctx); cause != nil { + observedErr = cause + } + metrics.RecordProvider(source, string(task.mode), len(task.keywords), len(jobs), started, observedErr) + metrics.AdapterFinished(task.ordinal) metrics.ScrapeRunsTotal.WithLabelValues(source).Inc() if err != nil { @@ -365,9 +383,8 @@ func logProviderRunStats(runStats *providerRunStats) { if sample := summary.ErrorSample; sample != nil { attrs = append(attrs, slog.Group("error_sample", "provider", sample.Provider, - "source", sample.Source, "mode", sample.Mode, - "error", sample.Error, + "errorType", metrics.ErrorType(fmt.Errorf("%s", sample.Error)), )) } slog.Info("scraper provider execution summary", attrs...) diff --git a/scraper-go/internal/pipeline/process.go b/scraper-go/internal/pipeline/process.go index 0f15d7a6..5a611695 100644 --- a/scraper-go/internal/pipeline/process.go +++ b/scraper-go/internal/pipeline/process.go @@ -3,6 +3,7 @@ package pipeline import ( "context" "log/slog" + "sync/atomic" "time" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/classifier" @@ -11,6 +12,7 @@ import ( "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/domain" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobindex" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/jobstore" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/redis/go-redis/v9" ) @@ -82,6 +84,16 @@ func processIncomingJobs( persistedByID := make(map[string]domain.Job) pending := make([]*domain.Job, 0, cfg.ClassificationBatchSize) indexBuf := make([]domain.Job, 0, cfg.IndexBatchSize) + var persistenceDepth, indexDepth, persistenceCapacity, indexCapacity atomic.Int64 + persistenceCapacity.Store(int64(cfg.ClassificationBatchSize)) + indexCapacity.Store(int64(cap(indexBuf))) + metrics.BindQueue("persistence", func() metrics.Queue { + return metrics.Queue{Depth: int(persistenceDepth.Load()), Capacity: int(persistenceCapacity.Load())} + }) + metrics.BindQueue("indexing", func() metrics.Queue { + return metrics.Queue{Depth: int(indexDepth.Load()), Capacity: int(indexCapacity.Load())} + }) + defer func() { persistenceDepth.Store(0); indexDepth.Store(0) }() approved := make([]domain.Job, 0) stats := ProcessStats{} batchNo := 0 @@ -109,6 +121,8 @@ func processIncomingJobs( n := min(cfg.IndexBatchSize, len(indexBuf)) chunk := append([]domain.Job(nil), indexBuf[:n]...) indexBuf = append([]domain.Job(nil), indexBuf[n:]...) + indexDepth.Store(int64(len(indexBuf))) + indexCapacity.Store(int64(cap(indexBuf))) if err := indexPersistedChunk(ctx, cfg, batchNo, chunk, &stats); err != nil { return err } @@ -126,6 +140,8 @@ func processIncomingJobs( continue } indexBuf = append(indexBuf, job) + indexDepth.Store(int64(len(indexBuf))) + indexCapacity.Store(int64(cap(indexBuf))) continue } replaced := false @@ -138,6 +154,8 @@ func processIncomingJobs( } if !replaced { indexBuf = append(indexBuf, job) + indexDepth.Store(int64(len(indexBuf))) + indexCapacity.Store(int64(cap(indexBuf))) } } return flushIndexBuffer(false) @@ -187,6 +205,7 @@ func processIncomingJobs( jobs = append(jobs, *job) } pending = pending[:0] + persistenceDepth.Store(0) batchDuplicates := windowDuplicates windowDuplicates = 0 persisted, err := processStageBatch(ctx, cfg, batchNo, jobs, &stats, batchDuplicates) @@ -229,6 +248,7 @@ func processIncomingJobs( } merged := dedup.Merge(&existing, &incoming) + metrics.Stage("classification") classification := classifier.Classify(*merged) merged.Classification = &classification if !classification.InScope && existing.Classification != nil { @@ -312,6 +332,7 @@ func processIncomingJobs( job = normalizeCollectedJob(job) keys := dedup.Keys(&job) if id, found := flushedID(flushed, keys); found { + metrics.JobResult(job.Source, "duplicate", 1) stats.Duplicates++ if err := mergeFlushed(job, id); err != nil { terminalErr = err @@ -319,6 +340,7 @@ func processIncomingJobs( continue } if existing := findSeen(seen, keys); existing != nil { + metrics.JobResult(job.Source, "duplicate", 1) stats.Duplicates++ windowDuplicates++ merged := dedup.Merge(existing, &job) @@ -331,6 +353,8 @@ func processIncomingJobs( ptr := &jobCopy indexSeen(seen, ptr) pending = append(pending, ptr) + persistenceDepth.Store(int64(len(pending))) + persistenceCapacity.Store(int64(cap(pending))) if err := flushPending(false); err != nil { terminalErr = err } @@ -382,14 +406,18 @@ func processStageBatch( duplicates int, ) ([]domain.Job, error) { started := time.Now() + metrics.Stage("classification") + defer metrics.AddProgress("batchesCompleted", 1) valid := make([]domain.Job, 0, len(jobs)) invalid := 0 for _, job := range jobs { if jobIsInvalid(job) { invalid++ + metrics.InvalidJob(job.Source) stats.Invalid++ continue } + metrics.JobResult(job.Source, "valid", 1) stats.Valid++ valid = append(valid, job) } @@ -455,6 +483,7 @@ func persistJobs( written := make([]domain.Job, 0, len(jobs)) inserted := 0 updated := 0 + metrics.Stage("persistence") for start := 0; start < len(jobs); start += cfg.PersistBatchSize { if cause := context.Cause(ctx); cause != nil { return written, inserted, updated, cause @@ -481,6 +510,9 @@ func persistJobs( } inserted += result.Inserted updated += result.Updated + for _, j := range result.Persisted { + metrics.JobResult(j.Source, "persisted", 1) + } written = append(written, result.Persisted...) } return written, inserted, updated, nil @@ -506,6 +538,7 @@ func indexPersistedChunk( var err error commands := 0 + metrics.Stage("indexing") if cfg.Index != nil { err = cfg.Index(ctx, jobs) } else if cfg.Store.Durable() { @@ -547,6 +580,9 @@ func indexPersistedChunk( "ids", len(ids), ) } + for _, j := range jobs { + metrics.JobResult(j.Source, "indexed", 1) + } stats.Indexed += len(jobs) slog.Info("scraper stage batch", "run_id", cfg.RunID, diff --git a/scraper-go/internal/pipeline/scrape.go b/scraper-go/internal/pipeline/scrape.go index 16322c66..c6f8deb1 100644 --- a/scraper-go/internal/pipeline/scrape.go +++ b/scraper-go/internal/pipeline/scrape.go @@ -60,7 +60,7 @@ func ScrapeAllSources( } defer release() } - slog.Info("starting scrape", "keywords", config.Keywords) + slog.Info("starting scrape", "keywords_total", len(config.Keywords), "run_id", config.RunID, "stage", "collection") slog.Info("scraper concurrency budget", "global_limit", config.MaxConcurrency, "provider_default_limit", config.ProviderMaxConcurrency, diff --git a/scraper-go/internal/pipeline/search.go b/scraper-go/internal/pipeline/search.go index 49863173..c8a5988b 100644 --- a/scraper-go/internal/pipeline/search.go +++ b/scraper-go/internal/pipeline/search.go @@ -6,6 +6,8 @@ import ( "log/slog" "time" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" + "github.com/redis/go-redis/v9" "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/cache" @@ -57,6 +59,7 @@ func SearchJobs( if err != nil { return SearchResult{}, err } + defer func() { metrics.FinishRun(resultErr, lease.RunID()) }() defer func() { releaseCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() @@ -84,8 +87,8 @@ func SearchJobs( if err := c.Set(runCtx, cacheKey, result, ttl); err != nil { slog.Error("pipeline.SearchJobs: cache write failed", - "key", cacheKey, - "error", err, + "stage", "cache", + "errorType", metrics.ErrorType(err), ) } diff --git a/scraper-go/internal/runlock/runlock.go b/scraper-go/internal/runlock/runlock.go index 0777884f..00218a38 100644 --- a/scraper-go/internal/runlock/runlock.go +++ b/scraper-go/internal/runlock/runlock.go @@ -9,6 +9,8 @@ import ( "log/slog" "sync" "time" + + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" ) var ( @@ -74,13 +76,18 @@ func (m *Manager) Acquire(ctx context.Context, source string) (*Lease, error) { acquired, err := m.store.TryAcquire(ctx, token, m.cfg.TTL) if err != nil { + metrics.Attempt(source, "failed") return nil, fmt.Errorf("%w: acquire: %v", ErrUnavailable, err) } if !acquired { + metrics.LockConflicts.WithLabelValues(metrics.Source(source)).Inc() + metrics.Attempt(source, "skipped") return nil, ErrAlreadyHeld } startedAt := m.now().UTC() + metrics.StartRun(source, startedAt, runID) + metrics.LockAcquired(m.cfg.TTL, runID) state := State{ RunID: runID, Source: source, @@ -91,7 +98,7 @@ func (m *Manager) Acquire(ctx context.Context, source string) (*Lease, error) { slog.Warn("scraper run state unavailable", "source", source, "run_id", runID, - "error", stateErr, + "errorType", metrics.ErrorType(stateErr), ) } @@ -157,6 +164,7 @@ func (l *Lease) State() State { func (l *Lease) Release(ctx context.Context) error { l.releaseOnce.Do(func() { + defer metrics.LockReleased(l.runID) l.cancel(nil) l.stopOnce.Do(func() { close(l.stopRenewal) @@ -170,7 +178,7 @@ func (l *Lease) Release(ctx context.Context) error { slog.Error("scraper run lock release failed", "source", l.source, "run_id", l.runID, - "error", err, + "errorType", metrics.ErrorType(err), ) case released: slog.Info("scraper run lock released", @@ -202,6 +210,7 @@ func (l *Lease) renew() { case <-l.stopRenewal: return case <-l.ctx.Done(): + metrics.Canceling(l.runID) return case <-safetyTimer.C: cause := fmt.Errorf("%w: renewal could not be confirmed before safety deadline", ErrLost) @@ -210,6 +219,9 @@ func (l *Lease) renew() { "run_id", l.runID, "reason", "renewal_safety_deadline", ) + metrics.LockLost.WithLabelValues(metrics.Source(l.source)).Inc() + metrics.LockReleased(l.runID) + metrics.Canceling(l.runID) l.cancel(cause) return case <-ticker.C: @@ -226,10 +238,11 @@ func (l *Lease) renew() { if l.ctx.Err() != nil { return } + metrics.LockRenewFailures.Inc() slog.Warn("scraper run lock renewal failed temporarily", "source", l.source, "run_id", l.runID, - "error", err, + "errorType", metrics.ErrorType(err), ) continue } @@ -240,10 +253,14 @@ func (l *Lease) renew() { "run_id", l.runID, "reason", "ownership_changed", ) + metrics.LockLost.WithLabelValues(metrics.Source(l.source)).Inc() + metrics.LockReleased(l.runID) + metrics.Canceling(l.runID) l.cancel(cause) return } + metrics.LockAcquired(l.manager.cfg.TTL, l.runID) resetTimer(safetyTimer, l.manager.cfg.TTL-l.manager.cfg.RenewInterval) } } diff --git a/scraper-go/internal/runlock/runlock_test.go b/scraper-go/internal/runlock/runlock_test.go index 3da0e323..7a49aa5d 100644 --- a/scraper-go/internal/runlock/runlock_test.go +++ b/scraper-go/internal/runlock/runlock_test.go @@ -8,7 +8,10 @@ import ( "testing" "time" + "github.com/Benevanio/Jobs_Scraper_Global/scraper-go/internal/metrics" "github.com/alicebob/miniredis/v2" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" "github.com/redis/go-redis/v9" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -185,6 +188,7 @@ func TestConfirmedOwnershipLossCancelsLease(t *testing.T) { } func TestTemporaryRenewalFailureDoesNotCancelLease(t *testing.T) { + metricBefore := testutil.ToFloat64(metrics.LockRenewFailures) var renewCalls atomic.Int32 store := &fakeStore{ renew: func(context.Context, State, time.Duration) (bool, error) { @@ -206,6 +210,7 @@ func TestTemporaryRenewalFailureDoesNotCancelLease(t *testing.T) { assert.NoError(t, context.Cause(lease.Context())) assert.GreaterOrEqual(t, renewCalls.Load(), int32(2)) + assert.Equal(t, metricBefore+1, testutil.ToFloat64(metrics.LockRenewFailures)) require.NoError(t, lease.Release(context.Background())) } @@ -344,3 +349,25 @@ func (s *fakeStore) Release(context.Context, string, string) (bool, error) { } return true, nil } + +func TestOperationalLockMetricsAndTokenExclusion(t *testing.T) { + manager, client, _ := newTestManager(t, 200*time.Millisecond, 25*time.Millisecond) + ctx := context.Background() + lease, err := manager.Acquire(ctx, "cron") + require.NoError(t, err) + require.True(t, metrics.Current().Lock.Held) + before := testutil.ToFloat64(metrics.LockConflicts.WithLabelValues("manual")) + _, err = manager.Acquire(ctx, "public_endpoint") + require.ErrorIs(t, err, ErrAlreadyHeld) + require.Equal(t, before+1, testutil.ToFloat64(metrics.LockConflicts.WithLabelValues("manual"))) + families, err := prometheus.DefaultGatherer.Gather() + require.NoError(t, err) + require.NotContains(t, fmt.Sprint(families), lease.Token()) + lost := testutil.ToFloat64(metrics.LockLost.WithLabelValues("cron")) + require.NoError(t, client.Set(ctx, LockKey, "different-owner", time.Second).Err()) + require.Eventually(t, func() bool { return context.Cause(lease.Context()) != nil }, time.Second, time.Millisecond) + require.Equal(t, lost+1, testutil.ToFloat64(metrics.LockLost.WithLabelValues("cron"))) + require.False(t, metrics.Current().Lock.Held) + require.GreaterOrEqual(t, metrics.Current().Lock.TTLSeconds, 0.0) + _ = lease.Release(ctx) +}