From cc17d957c74ef52547f9c9f1999545e8458b2619 Mon Sep 17 00:00:00 2001 From: Rafael Lopes Date: Fri, 10 Jul 2026 16:00:29 -0300 Subject: [PATCH] PERF: Reduz verbosidade de logs em nivel info no ciclo do cron Rebaixa para debug uma serie de logs "heartbeat" que disparavam todo ciclo (a cada 1 minuto) independente de qualquer mudanca real, competindo com os logs de acao/erro que realmente importam: buscas por watermark, contagem de tickets pendentes/monitorados, checagens de comentario ja sincronizado, abertura de conexao GLPI/PostgreSQL, e o resumo de sincronizacao do SN (que a margem de seguranca de 6h do watermark sempre retorna nao-vazio, mesmo sem mudanca real de campo). Corrige tambem um bug real encontrado em teste: no fluxo GLPI -> SN, todo comentario historico de um ticket era sanitizado e checado contra a API do SN a cada ciclo antes mesmo de verificar se ja tinha sido sincronizado (ticket_updates.destiny_id). Em tickets com historico longo isso significava dezenas de chamadas desnecessarias por minuto. Agora a checagem local (barata) roda primeiro, e so sanitiza/consulta o SN quando o comentario realmente ainda nao foi sincronizado. Corrige tambem o log de configuracao do pool PostgreSQL, que imprimia "[object Object]" por passar o objeto de config como mensagem em vez de metadado. LOG_LEVEL default muda de debug para info em .env.example e .env.production, unica forma do rebaixamento acima ter efeito pratico. Co-Authored-By: Claude Sonnet 5 --- .env.example | 2 +- src/controllers/processCommentsController.js | 6 ++-- src/controllers/processErrorController.js | 6 ++-- src/controllers/processSyncController.js | 12 +++---- .../processTicketLifecycleController.js | 4 +-- src/data/database.js | 8 ++--- src/data/glpiDataBase.js | 4 +-- src/models/ticketSnModel.js | 9 +++-- src/services/glpiCommentService.js | 34 ++++++++++++------- src/services/glpiTicketService.js | 6 ++-- src/services/servicenowService.js | 12 +++---- src/utils/commentSanitizer.js | 4 +-- src/utils/logger.js | 17 +++++++--- 13 files changed, 70 insertions(+), 54 deletions(-) diff --git a/.env.example b/.env.example index 8434155..c4b4b6f 100644 --- a/.env.example +++ b/.env.example @@ -79,7 +79,7 @@ SNGLPI_DB_PASSWORD= LOCATION_MAPPING_CSV_PATH=/path/to/your/location_mapping.csv # Logging -LOG_LEVEL=debug +LOG_LEVEL=info LOG_TO_CONSOLE=true LOG_RETENTION_DAYS=10 LOG_DIR=logs diff --git a/src/controllers/processCommentsController.js b/src/controllers/processCommentsController.js index 696c7e8..843c83b 100644 --- a/src/controllers/processCommentsController.js +++ b/src/controllers/processCommentsController.js @@ -2,11 +2,11 @@ const { fetchCommentsFromServiceNow } = require('../services/servicenowService') const { syncCommentsGlpitoSN, syncCommentsSNtoGlpi } = require('../services/glpiCommentService'); const TicketSyncModel = require('../models/ticketSyncModel'); const TicketGlpiModel = require('../models/ticketGlpiModel'); -const { logInfo } = require('../utils/logger'); +const { logDebug } = require('../utils/logger'); const processCommentsController = async () => { const ticketsToMonitor = await TicketSyncModel.getTicketsToMonitor(); - logInfo(`Tickets em monitoramento: ${ticketsToMonitor.length}`); + logDebug(`Tickets em monitoramento: ${ticketsToMonitor.length}`); for (const ticket of ticketsToMonitor) { const glpiStatus = await TicketGlpiModel.getTicketStatus(ticket.glpi_ticket_id); @@ -14,7 +14,7 @@ const processCommentsController = async () => { // Regra de negocio: enquanto o GLPI estiver Solucionado, nao manda comentario novo // do SN pra dentro do chamado. A decisao de reabertura acontece em // processTicketLifecycleController.js, que roda antes deste controlador no ciclo. - logInfo(`Ticket ${ticket.glpi_ticket_id} permanece Solucionado no GLPI. Comentarios SN -> GLPI bloqueados ate reabertura.`); + logDebug(`Ticket ${ticket.glpi_ticket_id} permanece Solucionado no GLPI. Comentarios SN -> GLPI bloqueados ate reabertura.`); await syncCommentsGlpitoSN(ticket); continue; } diff --git a/src/controllers/processErrorController.js b/src/controllers/processErrorController.js index b15796d..5acb246 100644 --- a/src/controllers/processErrorController.js +++ b/src/controllers/processErrorController.js @@ -1,15 +1,15 @@ const TicketSyncModel = require('../models/ticketSyncModel'); -const { logInfo, logError, logWarning } = require('../utils/logger'); +const { logInfo, logError, logWarning, logDebug } = require('../utils/logger'); const MAX_ERROR_RETRIES = Number(process.env.MAX_ERROR_RETRIES || 5); const processErrorController = async () => { - logInfo('Iniciando verificação de tickets com erro...'); + logDebug('Iniciando verificação de tickets com erro...'); try { const errorTickets = await TicketSyncModel.getTicketsInErrorState(); if (errorTickets.length === 0) { - logInfo('Nenhum ticket com erro encontrado para reprocessamento.'); + logDebug('Nenhum ticket com erro encontrado para reprocessamento.'); return; } diff --git a/src/controllers/processSyncController.js b/src/controllers/processSyncController.js index 34801bd..f7fff58 100644 --- a/src/controllers/processSyncController.js +++ b/src/controllers/processSyncController.js @@ -2,7 +2,7 @@ const TicketSnModel = require('../models/ticketSnModel'); const TicketSyncModel = require('../models/ticketSyncModel'); const SyncControlModel = require('../models/syncControlModel'); const { fetchTicketsFromServiceNow: fetchTicketsApi, fetchRequestsFromServiceNow: fetchRequestsApi, fetchScItemOptionValue } = require('../services/servicenowService'); -const { logInfo, logError, logSync } = require('../utils/logger'); +const { logInfo, logError, logSync, logDebug } = require('../utils/logger'); /** * Processa e salva um lote de tickets (incidentes ou requisicoes). @@ -22,7 +22,7 @@ const processAndSaveTickets = async (tickets, type) => { }; if (!tickets || tickets.length === 0) { - logInfo(`Nenhum ticket do tipo '${type}' para processar.`); + logDebug(`Nenhum ticket do tipo '${type}' para processar.`); return ''; } @@ -89,7 +89,7 @@ const processAndSaveTickets = async (tickets, type) => { logInfo(`Ticket ${ticket.number} recebido de novo pela margem de seguranca do watermark, sem mudanca de status ('${ticketStatus}'). Ignorando reset de 'source_last'.`); } } else { - logInfo(`Registro de sincronizacao para o ticket ${ticket.number?.value} ja existe. Nenhuma acao necessaria.`); + logDebug(`Registro de sincronizacao para o ticket ${ticket.number?.value} ja existe. Nenhuma acao necessaria.`); } const currentUpdateDate = parseServiceNowDate(ticket.sys_updated_on); @@ -114,12 +114,12 @@ const processAndSaveTickets = async (tickets, type) => { const processSyncController = async () => { try { const watermark = await SyncControlModel.getWatermark('servicenow'); - logInfo(`INFO: Buscando tickets do ServiceNow atualizados desde: ${watermark}`); + logDebug(`Buscando tickets do ServiceNow atualizados desde: ${watermark}`); const incidents = await fetchTicketsApi(watermark); const latestIncidentUpdate = await processAndSaveTickets(incidents, 'incidente'); - logInfo('INFO: Buscando requisicoes do ServiceNow...'); + logDebug('Buscando requisicoes do ServiceNow...'); const requests = await fetchRequestsApi(watermark); const latestRequestUpdate = await processAndSaveTickets(requests, 'requisicao'); @@ -131,7 +131,7 @@ const processSyncController = async () => { const nextWatermark = new Date(new Date(newWatermark).getTime() - sixHoursInMillis); await SyncControlModel.setWatermark('servicenow', nextWatermark); } else { - logInfo("Nenhum ticket novo ou atualizado encontrado. A marca d'agua nao foi alterada."); + logDebug("Nenhum ticket novo ou atualizado encontrado. A marca d'agua nao foi alterada."); } } catch (error) { diff --git a/src/controllers/processTicketLifecycleController.js b/src/controllers/processTicketLifecycleController.js index ac4cb3a..60203b5 100644 --- a/src/controllers/processTicketLifecycleController.js +++ b/src/controllers/processTicketLifecycleController.js @@ -12,7 +12,7 @@ const { } = require('../services/servicenowService'); const { isOutOfScopeSolution, handleOutOfScopeResolution, addServiceNowClosureNoteToGlpi } = require('../services/glpiTicketService'); const { stripHTML } = require('../utils/commentSanitizer'); -const { logInfo, logError, logWarning } = require('../utils/logger'); +const { logInfo, logError, logWarning, logDebug } = require('../utils/logger'); const DEFINITIVE_CLOSE_NOTICE = 'Chamado encerrado definitivamente. Tempo para reabertura encerrado. Caso necessario, por favor abra um novo Ticket.'; const caoaTiGroupId = process.env.SERVICENOW_CAOA_TI_GROUP_ID; @@ -85,7 +85,7 @@ const processTicketLifecycleController = async () => { try { const tickets = await TicketSyncModel.getTicketsForClosureMonitor(); if (!tickets.length) { - logInfo('Nenhum ticket ativo para monitoramento de status/fechamento.'); + logDebug('Nenhum ticket ativo para monitoramento de status/fechamento.'); return; } diff --git a/src/data/database.js b/src/data/database.js index 000c37e..1fa331d 100644 --- a/src/data/database.js +++ b/src/data/database.js @@ -1,7 +1,7 @@ // src/data/database.js // Configuração da conexão com o banco de dados PostgreSQL const { Pool } = require('pg'); -const { logInfo, logError } = require('../utils/logger'); +const { logInfo, logError, logDebug } = require('../utils/logger'); const poolConfig = { host: process.env.SNGLPI_DB_HOST , @@ -15,13 +15,11 @@ const pool = new Pool(poolConfig); // Log da configuração do pool para depuração (sem a senha) const sanitizedConfig = { ...poolConfig, password: '*****' }; -logInfo('--- Configuração do Pool PostgreSQL (Banco Intermediário) ---'); -logInfo(sanitizedConfig); -logInfo('----------------------------------------------------------'); +logInfo('Configuração do Pool PostgreSQL (Banco Intermediário)', sanitizedConfig); // testa a conexao pool.on('connect', () => { - logInfo('Conectado ao PostgreSQL'); + logDebug('Conectado ao PostgreSQL'); }); pool.on('error', (err) => { diff --git a/src/data/glpiDataBase.js b/src/data/glpiDataBase.js index e5bd960..4c1eab8 100644 --- a/src/data/glpiDataBase.js +++ b/src/data/glpiDataBase.js @@ -1,7 +1,7 @@ // src/data/glpiDatabase.js // Configuração da conexão com o banco de dados mariaDB do GLPI const mysql = require('mysql2/promise'); -const { logInfo, logError, logWarning } = require('../utils/logger'); +const { logError, logDebug } = require('../utils/logger'); const glpiPool = mysql.createPool({ host: process.env.GLPI_DB_HOST, @@ -18,7 +18,7 @@ const glpiPool = mysql.createPool({ // Testar conexão glpiPool.on('connection', (connection) => { - logInfo('Nova conexão GLPI estabelecida'); + logDebug('Nova conexão GLPI estabelecida'); }); glpiPool.on('error', (err) => { diff --git a/src/models/ticketSnModel.js b/src/models/ticketSnModel.js index fb996f5..17b44ec 100644 --- a/src/models/ticketSnModel.js +++ b/src/models/ticketSnModel.js @@ -1,5 +1,5 @@ const pool = require('../data/database'); -const { logInfo, logError } = require('../utils/logger'); +const { logInfo, logError, logDebug } = require('../utils/logger'); class TicketSnModel { @@ -94,7 +94,10 @@ class TicketSnModel { action: 'insert' }); } else { - logInfo(`🔄 Ticket atualizado! ID: ${result.rows[0].id}`, { + // Fica em debug: a margem de seguranca de 6h do watermark reenvia o mesmo ticket + // toda vez que ele ainda esta "quente", mesmo sem mudanca real de campo. O sinal + // de mudanca de status de verdade ja e logado em processSyncController.js. + logDebug(`🔄 Ticket atualizado! ID: ${result.rows[0].id}`, { ticket_id: result.rows[0].id, ticket_number: values[0], action: 'update' @@ -137,7 +140,7 @@ class TicketSnModel { `; const result = await pool.query(query); - logInfo(`📋 Tickets pendentes encontrados: ${result.rows.length}`); + logDebug(`📋 Tickets pendentes encontrados: ${result.rows.length}`); return result.rows; } catch (error) { diff --git a/src/services/glpiCommentService.js b/src/services/glpiCommentService.js index f5aaf6f..42fe504 100644 --- a/src/services/glpiCommentService.js +++ b/src/services/glpiCommentService.js @@ -1,7 +1,7 @@ const TicketGlpiModel = require('../models/ticketGlpiModel'); const TicketSyncModel = require('../models/ticketSyncModel'); const TicketUpdateModel = require('../models/ticketUpdateModel'); -const { logInfo, logError } = require('../utils/logger'); +const { logInfo, logError, logDebug } = require('../utils/logger'); const { existingCommentInServiceNow, syncCommentToServiceNow } = require('./servicenowService'); const { sanitizeGLPIComment } = require('../utils/commentSanitizer'); @@ -81,29 +81,37 @@ const formatSNUpdateForGlpi = (update, options = {}) => { const syncCommentsGlpitoSN = async (ticket) => { try { - logInfo('INFO: Iniciando sincronizacao de comments do GLPI para o ServiceNow...'); + logDebug('Iniciando sincronizacao de comments do GLPI para o ServiceNow...'); const comments = await TicketGlpiModel.getFollowupsByItemId(ticket.glpi_ticket_id); await TicketSyncModel.updateLastSync(ticket.sn_ticket_id, 'glpi'); // Atualiza o timestamp if (!Array.isArray(comments) || comments.length === 0) { - logInfo(`Nenhum comentario encontrado no GLPI para o ticket GLPI ID: ${ticket.glpi_ticket_id}`); + logDebug(`Nenhum comentario encontrado no GLPI para o ticket GLPI ID: ${ticket.glpi_ticket_id}`); return; } - logInfo(`INFO: ${comments.length} comentarios encontrados (GLPI ID: ${ticket.glpi_ticket_id})`); + logDebug(`${comments.length} comentarios encontrados (GLPI ID: ${ticket.glpi_ticket_id})`); let hasError = false; + const syncId = await TicketSyncModel.getIdSyncByGlpiId(ticket.glpi_ticket_id); for (const comment of comments) { try { - const sanitized = sanitizeGLPIComment(comment); + // Checa idempotencia local (barato, sem chamada externa) antes de sanitizar e consultar o SN. + // A maioria dos comentarios de um ticket ja monitorado ha varios ciclos ja tem destiny_id + // gravado, entao nem precisa sanitizar nem chamar a API do SN pra saber disso. const existingComment = await TicketUpdateModel.getBySourceId(comment.id); - const existsInSN = await existingCommentInServiceNow(ticket.sn_ticket_id, sanitized); - const syncId = await TicketSyncModel.getIdSyncByGlpiId(ticket.glpi_ticket_id); - - if (existingComment && existsInSN) { - logInfo(`INFO: Comentario ${comment.id} ja sincronizado.`); + if (existingComment && existingComment.destiny_id) { + logDebug(`Comentario ${comment.id} ja sincronizado.`); continue; } - + + const sanitized = sanitizeGLPIComment(comment); + const existsInSN = await existingCommentInServiceNow(ticket.sn_ticket_id, sanitized); + + if (existingComment && existsInSN) { + logDebug(`Comentario ${comment.id} ja sincronizado.`); + continue; + } + if (!existingComment && existsInSN) { await TicketUpdateModel.insert({ ticket_sync_id: syncId, @@ -157,7 +165,7 @@ const syncCommentsGlpitoSN = async (ticket) => { await TicketSyncModel.updateStatus(ticket.sn_ticket_id, finalGlpiStatus, finalSnStatus); } - logInfo('OK: Sincronizacao de comentarios GLPI -> SN concluida!'); + logDebug('OK: Sincronizacao de comentarios GLPI -> SN concluida!'); } catch (error) { logError(`Erro geral na sincronizacao: ${error}`); } @@ -165,7 +173,7 @@ const syncCommentsGlpitoSN = async (ticket) => { const syncCommentsSNtoGlpi = async (comments, ticket, options = {}) => { - logInfo('INFO: Iniciando sincronizacao de comments do ServiceNow para o GLPI...'); + logDebug('Iniciando sincronizacao de comments do ServiceNow para o GLPI...'); const orderedComments = [...comments].sort((a, b) => { const aTime = new Date(a.created_at).getTime(); diff --git a/src/services/glpiTicketService.js b/src/services/glpiTicketService.js index d338b62..8ed0073 100644 --- a/src/services/glpiTicketService.js +++ b/src/services/glpiTicketService.js @@ -2,7 +2,7 @@ const TicketSnModel = require('../models/ticketSnModel'); const TicketGlpiModel = require('../models/ticketGlpiModel'); const TicketUpdateModel = require('../models/ticketUpdateModel'); const TicketSyncModel = require('../models/ticketSyncModel'); -const { logInfo, logError } = require('../utils/logger'); +const { logInfo, logError, logDebug } = require('../utils/logger'); const { addWorkNoteToServiceNow, updateExternalTicketInServiceNow, queueExternalTicketLinkRetry, reassignTicketInServiceNow } = require('./servicenowService'); const { stripHTML } = require('../utils/commentSanitizer'); @@ -11,11 +11,11 @@ const caoaTiGroupId = process.env.SERVICENOW_CAOA_TI_GROUP_ID; const syncTicketsToGlpi = async () => { try { - logInfo('🔄 Iniciando sincronização para GLPI...'); + logDebug('🔄 Iniciando sincronização para GLPI...'); const pendingTickets = await TicketSnModel.getPendingTickets(); if (pendingTickets.length === 0) { - logInfo('✅ Nenhum ticket pendente para sincronizar'); + logDebug('✅ Nenhum ticket pendente para sincronizar'); return; } diff --git a/src/services/servicenowService.js b/src/services/servicenowService.js index 1bf43f9..77941c2 100644 --- a/src/services/servicenowService.js +++ b/src/services/servicenowService.js @@ -3,7 +3,7 @@ const axios = require('axios'); const apiConfig = require('../../config/apiConfig'); const { stripHTML } = require('../utils/commentSanitizer'); const TicketSnModel = require('../models/ticketSnModel'); -const { logInfo, logError, logSync } = require('../utils/logger'); +const { logInfo, logError, logSync, logDebug } = require('../utils/logger'); const TicketUpdateModel = require('../models/ticketUpdateModel'); const TicketSyncModel = require('../models/ticketSyncModel'); @@ -261,7 +261,7 @@ const existingCommentInServiceNow = async (ticketId, comment) => { const fetchCommentsFromServiceNow = async (ticket) => { try { - logInfo(`Iniciando busca de comentarios/worknotes do ServiceNow para o ticket SN Ticket: ${ticket.glpi_ticket_id}`); + logDebug(`Iniciando busca de comentarios/worknotes do ServiceNow para o ticket SN Ticket: ${ticket.glpi_ticket_id}`); const sys_id = ticket.sys_id; @@ -281,7 +281,7 @@ const fetchCommentsFromServiceNow = async (ticket) => { sysparm_limit: pageSize, sysparm_offset: offset }; - logInfo(`Buscando pagina ${page} de comentarios do ticket SN Ticket: ${ticket.glpi_ticket_id}`); + logDebug(`Buscando pagina ${page} de comentarios do ticket SN Ticket: ${ticket.glpi_ticket_id}`); const response = await axios.get(apiConfig.snTableJournalConfig.baseUrl, { auth: apiConfig.servicenowAuthentication.auth, params @@ -338,11 +338,11 @@ const fetchCommentsFromServiceNow = async (ticket) => { return aTime - bTime; }); if (orderedComments.length === 0) { - logInfo(`Nenhum comentario/worknote encontrado no Service Now para o ticket GLPI ID: ${ticket.glpi_ticket_id}`); + logDebug(`Nenhum comentario/worknote encontrado no Service Now para o ticket GLPI ID: ${ticket.glpi_ticket_id}`); return []; } - logInfo(`Encontrado ${orderedComments.length} atualizacoes (comments/work_notes) para o ticket SN Ticket: ${ticket.glpi_ticket_id}`) + logDebug(`Encontrado ${orderedComments.length} atualizacoes (comments/work_notes) para o ticket SN Ticket: ${ticket.glpi_ticket_id}`) const commentsInserted = []; @@ -351,7 +351,7 @@ const fetchCommentsFromServiceNow = async (ticket) => { const existingComment = await TicketUpdateModel.getBySourceId(comment.sys_id); if (existingComment) { - logInfo(`Comentario: ${comment.sys_id} ja existe no banco de dados`, { step: 3 }); + logDebug(`Comentario: ${comment.sys_id} ja existe no banco de dados`, { step: 3 }); continue; } else { diff --git a/src/utils/commentSanitizer.js b/src/utils/commentSanitizer.js index 0ec51c1..9988602 100644 --- a/src/utils/commentSanitizer.js +++ b/src/utils/commentSanitizer.js @@ -1,4 +1,4 @@ -const { logInfo, logWarning } = require('./logger'); +const { logDebug, logWarning } = require('./logger'); const stripHTML = (html) => { if (!html) return ''; @@ -76,7 +76,7 @@ const sanitizeGLPIComment = (commentObj) => { content = stripHTML(content); if (content !== commentObj.content) { - logInfo('🔧 Comentário sanitizado', { + logDebug('🔧 Comentário sanitizado', { original: commentObj.content.substring(0, 100) + '...', cleaned: content.substring(0, 100) + '...' }); diff --git a/src/utils/logger.js b/src/utils/logger.js index 8546018..b12027d 100644 --- a/src/utils/logger.js +++ b/src/utils/logger.js @@ -94,12 +94,18 @@ const logWarning = (message, meta = {}) => { logger.warn(message, meta); }; -// Log de sincronização específico +const logDebug = (message, meta = {}) => { + logger.debug(message, meta); +}; + +// Log de sincronização específico. Fica em debug: por causa da margem de seguranca do +// watermark, esse log dispara toda vez que ha qualquer ticket "quente" no lote, mesmo sem +// mudanca real de campo - o sinal de mudanca de verdade e logado no chamador. const logSync = (service, count, type) => { - logger.info(`SYNC: ${service} - ${count} ${type} sincronizados`, { - service, - count, - type + logger.debug(`SYNC: ${service} - ${count} ${type} sincronizados`, { + service, + count, + type }); }; @@ -108,5 +114,6 @@ module.exports = { logError, logInfo, logWarning, + logDebug, logSync, };