From 5ea25d462e095d3721f7b1504fff3253727ed9c0 Mon Sep 17 00:00:00 2001 From: "kevin.lhereec" Date: Fri, 17 Jul 2026 10:36:57 +0200 Subject: [PATCH] feat: logs debug sur les echanges XML CWMP - cwmp_middleware: log XML brut recu (bodyPreview 500 chars), contentType, bodyLength, et message extrait (type, cwmpVersion, cwmpId, messageKeys) + log body vide (CPE polling) - cwmp_logger_middleware: log XML pretty-print complet CPE->ACS et ACS->CPE en debug, independamment du statut trace - cwmp_controller: log routage message (messageType), InformResponse, TransferCompleteResponse, reponses state machine avec longueur --- app/controllers/cwmp_controller.ts | 17 ++++++++++++++++- app/middleware/cwmp_logger_middleware.ts | 19 +++++++++++++++++++ app/middleware/cwmp_middleware.ts | 24 ++++++++++++++++++++++++ 3 files changed, 59 insertions(+), 1 deletion(-) diff --git a/app/controllers/cwmp_controller.ts b/app/controllers/cwmp_controller.ts index b82ae0e..1589977 100644 --- a/app/controllers/cwmp_controller.ts +++ b/app/controllers/cwmp_controller.ts @@ -43,7 +43,10 @@ export default class CwmpController { const hashId = manager.getHashIdForRemote(remoteKey) if (hashId) ctx.cwmpDeviceId = hashId - logger.debug({ remoteKey, sessionId, rebound, hashId, hasSession: manager.hasSession(sessionId) }, 'CWMP Empty POST received') + logger.debug( + { remoteKey, sessionId, rebound, hashId, hasSession: manager.hasSession(sessionId) }, + 'CWMP empty POST — CPE polling for next task' + ) if (manager.hasSession(sessionId)) { const result = await manager.continue(sessionId) @@ -54,6 +57,11 @@ export default class CwmpController { return response.status(204).send('') } + logger.debug( + { sessionId, remoteKey, messageType: message?.type ?? 'none', cwmpId: envelope?.header?.id }, + 'CWMP message routing' + ) + if (message?.type === 'Inform') { const { xml, hashId } = await this.handleInform( message.data, @@ -64,12 +72,14 @@ export default class CwmpController { request.header('x-forwarded-for') || '' ) ctx.cwmpDeviceId = hashId + logger.debug({ sessionId, hashId, responseLength: xml.length }, 'CWMP sending InformResponse') return this.sendSoap(response, xml) } if (message?.type === 'TransferComplete') { const hashId = manager.getHashIdForRemote(remoteKey) if (hashId) ctx.cwmpDeviceId = hashId + logger.debug({ sessionId, hashId }, 'CWMP sending TransferCompleteResponse') const resp = buildSoapEnvelope( undefined, '' @@ -83,8 +93,13 @@ export default class CwmpController { if (message && manager.hasSession(sessionId)) { const { success, payload } = this.getMessageInfo(message) + logger.debug( + { sessionId, hashId, messageType: message.type, success }, + 'CWMP forwarding response to state machine' + ) const result = await manager.handleCWMPResponse(sessionId, success, payload) if (result && result !== '') { + logger.debug({ sessionId, hashId, responseLength: result.length }, 'CWMP state machine produced response') return this.sendSoap(response, result) } } diff --git a/app/middleware/cwmp_logger_middleware.ts b/app/middleware/cwmp_logger_middleware.ts index 8cc1872..f903ff3 100644 --- a/app/middleware/cwmp_logger_middleware.ts +++ b/app/middleware/cwmp_logger_middleware.ts @@ -105,5 +105,24 @@ export default class CwmpLoggerMiddleware { // Brief app-level log only (no SOAP body) logger.debug({ sessionId, deviceId: deviceId ?? 'unknown' }, 'TR-069 exchange (not traced)') } + + // Always log full XML at debug level regardless of trace status + if (rawBody && rawBody.trim() !== '') { + logger.debug( + { sessionId, deviceId: deviceId ?? 'unknown', direction: 'CPE→ACS', xml: this.prettyXml(rawBody) }, + 'CWMP XML request' + ) + } + if (capturedResponseXml) { + logger.debug( + { sessionId, deviceId: deviceId ?? 'unknown', direction: 'ACS→CPE', xml: this.prettyXml(capturedResponseXml) }, + 'CWMP XML response' + ) + } else if (isEmptyResponse) { + logger.debug( + { sessionId, deviceId: deviceId ?? 'unknown', direction: 'ACS→CPE' }, + 'CWMP empty response (204)' + ) + } } } diff --git a/app/middleware/cwmp_middleware.ts b/app/middleware/cwmp_middleware.ts index f65d78c..d17d689 100644 --- a/app/middleware/cwmp_middleware.ts +++ b/app/middleware/cwmp_middleware.ts @@ -1,6 +1,7 @@ import type { HttpContext } from '@adonisjs/core/http' import type { NextFn } from '@adonisjs/core/types/http' import { parseSoapXml, extractCwmpMessage } from '../protocol/soap.js' +import logger from '@adonisjs/core/services/logger' /** * CWMP Middleware @@ -38,9 +39,21 @@ export default class CwmpMiddleware { // Empty body = CPE polling for next instruction (valid in TR-069) if (request.cwmp.isEmpty) { + logger.debug({ sessionId, remoteIp }, 'CWMP empty POST (CPE polling)') return next() } + logger.debug( + { + sessionId, + remoteIp, + contentType, + bodyLength: rawBody.length, + bodyPreview: rawBody.slice(0, 500), + }, + 'CWMP XML received' + ) + // Validate content type for non-empty requests const isXml = contentType.includes('text/xml') || @@ -62,6 +75,17 @@ export default class CwmpMiddleware { // Extract CWMP message from envelope body const message = extractCwmpMessage(envelope.body) request.cwmp.message = message + + logger.debug( + { + sessionId, + cwmpVersion: envelope.cwmpVersion, + cwmpId: envelope.header?.id, + messageType: message?.type ?? 'unknown', + messageKeys: message?.data ? Object.keys(message.data) : [], + }, + 'CWMP XML parsed' + ) } catch (error: any) { logger.error({ sessionId, error: error.message }, 'CWMP XML parse error') response.status(400).send('Malformed SOAP/XML')