From c9a4be04754b46a895fe142cb653e56497fa0b25 Mon Sep 17 00:00:00 2001 From: Zaid Abdulla Date: Mon, 8 Nov 2021 12:21:02 -0800 Subject: [PATCH] Deubg log for HTTP and HTTPS client errors --- bin/genieacs-cwmp.ts | 1 + lib/cwmp.ts | 35 +++++++++++++++++++++++++++-------- lib/debug.ts | 26 +++++++++++++++++++++++--- lib/forwarded.ts | 12 +++++++----- lib/nbi.ts | 4 +++- lib/server.ts | 38 ++++++++++++++++++++++++++++++++++++++ 6 files changed, 99 insertions(+), 17 deletions(-) diff --git a/bin/genieacs-cwmp.ts b/bin/genieacs-cwmp.ts index 6e01d95..1a5dd82 100755 --- a/bin/genieacs-cwmp.ts +++ b/bin/genieacs-cwmp.ts @@ -83,6 +83,7 @@ if (!cluster.worker) { host: SERVICE_ADDRESS, ssl: key && cert ? { key, cert } : null, onConnection: cwmp.onConnection, + onClientError: cwmp.onClientError, timeout: 30000, keepAliveTimeout: 0, }; diff --git a/lib/cwmp.ts b/lib/cwmp.ts index 9b0fc8e..43d7d4e 100644 --- a/lib/cwmp.ts +++ b/lib/cwmp.ts @@ -54,6 +54,7 @@ import { decode, encodingExists } from "iconv-lite"; import { parseXmlDeclaration } from "./xml-parser"; import * as debug from "./debug"; import { getRequestOrigin } from "./forwarded"; +import { getSocketEndpoints } from "./server"; const gzipPromisified = promisify(zlib.gzip); const deflatePromisified = promisify(zlib.deflate); @@ -883,16 +884,8 @@ async function sendAcsRequest( return writeResponse(sessionContext, res); } -// Only needed to prevent tree shaking from removing the remoteAddress -// workaround in onConnection function. -const remoteAddressWorkaround = new WeakMap(); - // When socket closes, store active sessions in cache export function onConnection(socket: Socket): void { - // The property remoteAddress may be undefined after the connection is - // closed, unless we read it at least once (caching?) - remoteAddressWorkaround.set(socket, socket.remoteAddress); - socket.on("close", async () => { const sessionContext = currentSessions.get(socket); if (!sessionContext) return; @@ -947,6 +940,32 @@ export function onConnection(socket: Socket): void { }); } +export function onClientError(err: Error, socket: Socket): void { + const remoteAddress = getSocketEndpoints(socket).remoteAddress; + localCache + .getCurrentSnapshot() + .then((cacheSnapshot) => { + const debugEnabled = !!localCache.getConfig( + cacheSnapshot, + "cwmp.debug", + { + remoteAddress: remoteAddress, + }, + Date.now(), + (e) => { + if (Array.isArray(e) && e[0] === "FUNC" && e[1] === "REMOTE_ADDRESS") + return remoteAddress; + return e; + } + ); + + if (debugEnabled) debug.clientError(remoteAddress, err); + }) + .catch((err) => { + throw err; + }); +} + setInterval(() => { if (stats.droppedRequests) { logger.warn({ diff --git a/lib/debug.ts b/lib/debug.ts index e1dee3c..444c1eb 100644 --- a/lib/debug.ts +++ b/lib/debug.ts @@ -22,6 +22,7 @@ import { Socket } from "net"; import { appendFileSync } from "fs"; import { stringify } from "./common/yaml"; import * as config from "./config"; +import { getSocketEndpoints } from "./server"; const DEBUG_FILE = "" + config.get("DEBUG_FILE"); const DEBUG_FORMAT = "" + config.get("DEBUG_FORMAT"); @@ -45,13 +46,14 @@ export function incomingHttpRequest( if (!DEBUG_FILE) return; const now = new Date(); const con = httpRequest.socket; + const socketEndpoints = getSocketEndpoints(con); const msg = { event: "incoming HTTP request", timestamp: now, - remoteAddress: con.remoteAddress, + remoteAddress: socketEndpoints.remoteAddress, deviceId: deviceId, connection: getConnectionTimestamp(con), - localPort: con.localPort, + localPort: socketEndpoints.localPort, method: httpRequest.method, url: httpRequest.url, headers: httpRequest.headers, @@ -73,10 +75,11 @@ export function outgoingHttpResponse( if (!DEBUG_FILE) return; const now = new Date(); const con = httpResponse.socket; + const socketEndpoints = getSocketEndpoints(con); const msg = { event: "outgoing HTTP response", timestamp: now, - remoteAddress: con.remoteAddress, + remoteAddress: socketEndpoints.remoteAddress, deviceId: deviceId, connection: getConnectionTimestamp(con), statusCode: httpResponse.statusCode, @@ -199,3 +202,20 @@ export function outgoingUdpMessage( appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n"); else throw new Error(`Unrecognized DEBUG_FORMAT option`); } + +export function clientError(remoteAddress: string, err: Error): void { + if (!DEBUG_FILE) return; + const now = new Date(); + const msg = { + event: "client error", + timestamp: now, + remoteAddress: remoteAddress, + error: err.message, + }; + + if (DEBUG_FORMAT === "yaml") + appendFileSync(DEBUG_FILE, "---\n" + stringify(msg)); + else if (DEBUG_FORMAT === "json") + appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n"); + else throw new Error(`Unrecognized DEBUG_FORMAT option`); +} diff --git a/lib/forwarded.ts b/lib/forwarded.ts index f8cab26..c73eac0 100644 --- a/lib/forwarded.ts +++ b/lib/forwarded.ts @@ -21,6 +21,7 @@ import { IncomingMessage } from "http"; import { TLSSocket } from "tls"; import { parseCIDR, parse, IPv6, IPv4 } from "ipaddr.js"; import * as config from "./config"; +import { getSocketEndpoints } from "./server"; interface RequestOrigin { localAddress: string; @@ -98,18 +99,19 @@ export function getRequestOrigin(request: IncomingMessage): RequestOrigin { let origin = cache.get(request); if (!origin) { const soc = request.socket; + const socketEndpoints = getSocketEndpoints(soc); origin = { - localAddress: soc.localAddress, - localPort: soc.localPort, - remoteAddress: soc.remoteAddress, - remotePort: soc.remotePort, + localAddress: socketEndpoints.localAddress, + localPort: socketEndpoints.localPort, + remoteAddress: socketEndpoints.remoteAddress, + remotePort: socketEndpoints.remotePort, host: request.headers["host"], encrypted: !!(request.socket as TLSSocket).encrypted, }; const header = request.headers["forwarded"]; if (header) { - const ip = parse(soc.remoteAddress) as IPv4; + const ip = parse(socketEndpoints.remoteAddress) as IPv4; if (cidrs.some((cidr) => ip.match(cidr as [IPv4, number]))) { const parsed = parseForwardedHeader(header); diff --git a/lib/nbi.ts b/lib/nbi.ts index e53c18a..ec1cc4f 100644 --- a/lib/nbi.ts +++ b/lib/nbi.ts @@ -30,6 +30,7 @@ import { version as VERSION } from "../package.json"; import { ping } from "./ping"; import * as logger from "./logger"; import { flattenDevice } from "./mongodb-functions"; +import { getSocketEndpoints } from "./server"; const DEVICE_TASKS_REGEX = /^\/devices\/([a-zA-Z0-9\-_%]+)\/tasks\/?$/; const TASKS_REGEX = /^\/tasks\/([a-zA-Z0-9\-_%]+)(\/[a-zA-Z_]*)?$/; @@ -101,10 +102,11 @@ export function listener( request.addListener("end", () => { const body = getBody(); const urlParts = url.parse(request.url, true); + const socketEndpoints = getSocketEndpoints(request.socket); logger.accessInfo( Object.assign({}, urlParts.query, { - remoteAddress: request.socket.remoteAddress, + remoteAddress: socketEndpoints.remoteAddress, message: `${request.method} ${urlParts.pathname}`, }) ); diff --git a/lib/server.ts b/lib/server.ts index 21b8fb9..47d1d2f 100644 --- a/lib/server.ts +++ b/lib/server.ts @@ -59,8 +59,20 @@ interface ServerOptions { timeout?: number; keepAliveTimeout?: number; onConnection?: (socket: Socket) => void; + onClientError?: (err: Error, socket: Socket) => void; } +interface SocketEndpoint { + localAddress: string; + localPort: number; + remoteAddress: string; + remotePort: number; + remoteFamily: "IPv4" | "IPv6"; +} + +// Save this info as they're not accessible after a socket has been closed +const socketEndpoints: WeakMap = new WeakMap(); + export function start( options: ServerOptions, _listener: http.RequestListener @@ -85,6 +97,27 @@ export function start( if (options.onConnection) server.on("connection", options.onConnection); } + server.on("connection", (socket: Socket) => { + socketEndpoints.set(socket, { + localAddress: socket.localAddress, + localPort: socket.localPort, + remoteAddress: socket.remoteAddress, + remotePort: socket.remotePort, + remoteFamily: socket.remoteFamily as "IPv4" | "IPv6", + }); + }); + + if (options.onClientError) { + server.on("clientError", (err, socket: Socket) => { + if (err["code"] !== "ECONNRESET" && socket.writable) + socket.end("HTTP/1.1 400 Bad Request\r\nConnection: close\r\n\r\n"); + + // As per Node docs: This event is guaranteed to be passed an instance + // of the class + options.onClientError(err, socket as Socket); + }); + } + server.timeout = options.timeout || 0; if (options.keepAliveTimeout != null) server.keepAliveTimeout = options.keepAliveTimeout; @@ -99,3 +132,8 @@ export function stop(): Promise { closeServer(20000, resolve); }); } + +export function getSocketEndpoints(socket: Socket): SocketEndpoint { + // TLSSocket keeps a reference to the raw TCP socket in _parent + return socketEndpoints.get(socket["_parent"] ?? socket); +}