Reimplement CPE debug log

.gitignore

@@ -1,7 +1,6 @@
 *~
 node_modules
 dist
-debug
 config/config.json
 config/config-ui.json
 config/cwmp.key

build/build.ts

@@ -53,6 +53,7 @@ const externals = [
   "stream",
   "mithril",
   "parsimmon",
+  "yaml",
   "codemirror",
   "codemirror/mode/javascript/javascript",
   "codemirror/mode/yaml/yaml"
@@ -78,7 +79,6 @@ async function init(): Promise<void> {
   fs.mkdirSync(OUTPUT_DIR);
   fs.mkdirSync(OUTPUT_DIR + "/bin");
   fs.mkdirSync(OUTPUT_DIR + "/config");
-  fs.mkdirSync(OUTPUT_DIR + "/debug");
   fs.mkdirSync(OUTPUT_DIR + "/public");
   fs.mkdirSync(OUTPUT_DIR + "/tools");
 

config/config-sample.json

@@ -9,6 +9,5 @@
   "FS_HOSTNAME" : "acs.example.com",
   "UI_INTERFACE" : "0.0.0.0",
   "UI_PORT" : 3000,
-  "UI_JWT_SECRET": "",
-  "DEBUG" : false
+  "UI_JWT_SECRET": ""
 }

lib/api-functions.ts

@@ -17,6 +17,7 @@
  * along with GenieACS.  If not, see <http://www.gnu.org/licenses/>.
  */
 
+import { parse } from "url";
 import * as db from "./db";
 import * as common from "./common";
 import * as cache from "./cache";
@@ -76,6 +77,9 @@ export async function connectionRequest(deviceId): Promise<void> {
     serialNumber: device["_deviceId"]["SerialNumber"],
     productClass: device["_deviceId"]["ProductClass"],
     oui: device["_deviceId"]["OUI"],
+    remoteAddress: connectionRequestUrl
+      ? parse(connectionRequestUrl).host
+      : null,
     username: username || "",
     password: password || ""
   };
@@ -114,13 +118,17 @@ export async function connectionRequest(deviceId): Promise<void> {
     ] as Expression;
   }
 
+  const debug = !!getConfig(snapshot, "cwmp.debug", context, now);
+
   let udpProm;
   if (udpConnectionRequestAddress) {
     udpProm = udpConnectionRequest(
       udpConnectionRequestAddress,
       authExp,
       context,
-      UDP_CONNECTION_REQUEST_PORT
+      UDP_CONNECTION_REQUEST_PORT,
+      debug,
+      deviceId
     );
   }
 
@@ -130,7 +138,9 @@ export async function connectionRequest(deviceId): Promise<void> {
       authExp,
       context,
       CONNECTION_REQUEST_ALLOW_BASIC_AUTH,
-      CONNECTION_REQUEST_TIMEOUT
+      CONNECTION_REQUEST_TIMEOUT,
+      debug,
+      deviceId
     );
   } catch (err) {
     if (!udpProm) throw err;

lib/config.ts

@@ -80,6 +80,8 @@ const options = {
   DOWNLOAD_TIMEOUT: { type: "int", default: 3600 },
   EXT_TIMEOUT: { type: "int", default: 3000 },
   MAX_CACHE_TTL: { type: "int", default: 86400 },
+  DEBUG_FILE: { type: "path", default: "" },
+  DEBUG_FORMAT: { type: "string", default: "yaml" },
   DEBUG: { type: "bool", default: false },
   RETRY_DELAY: { type: "int", default: 300 },
   SESSION_TIMEOUT: { type: "int", default: 30 },

lib/connection-request.ts

@@ -25,6 +25,7 @@ import { evaluateAsync } from "./common/expression";
 import { Expression } from "./types";
 import * as auth from "./auth";
 import * as extensions from "./extensions";
+import * as debug from "./debug";
 
 async function extractAuth(
   exp: Expression,
@@ -62,18 +63,25 @@ async function extractAuth(
 }
 
 function httpGet(
-  options: {},
-  timeout
+  options: http.RequestOptions,
+  timeout,
+  _debug: boolean,
+  deviceId: string
 ): Promise<{ statusCode: number; headers: {} }> {
   return new Promise((resolve, reject) => {
     const req = http
       .get(options, res => {
         res.resume();
         resolve({ statusCode: res.statusCode, headers: res.headers });
+        if (_debug) {
+          debug.outgoingHttpRequest(req, deviceId, options, null);
+          debug.incomingHttpResponse(res, deviceId, null);
+        }
       })
-      .on("error", () => {
+      .on("error", err => {
         req.abort();
         reject(new Error("Device is offline"));
+        if (_debug) debug.outgoingHttpRequestError(req, deviceId, options, err);
       })
       .on("socket", socket => {
         socket.setTimeout(timeout);
@@ -89,7 +97,9 @@ export async function httpConnectionRequest(
   authExp: Expression,
   context: {},
   allowBasicAuth: boolean,
-  timeout: number
+  timeout: number,
+  _debug: boolean,
+  deviceId: string
 ): Promise<void> {
   const now = Date.now();
   const options: http.RequestOptions = parse(address);
@@ -141,10 +151,11 @@ export async function httpConnectionRequest(
       }
     }
 
-    let res = await httpGet(opts, timeout);
+    let res = await httpGet(opts, timeout, _debug, deviceId);
 
     // Workaround for some devices unexpectedly closing the connection
-    if (res.statusCode === 0 && authHeader) res = await httpGet(opts, timeout);
+    if (res.statusCode === 0 && authHeader)
+      res = await httpGet(opts, timeout, _debug, deviceId);
     if (res.statusCode === 0) throw new Error("Device is offline");
     if (res.statusCode === 200 || res.statusCode === 204) return;
 
@@ -171,7 +182,9 @@ export async function udpConnectionRequest(
   address: string,
   authExp: Expression,
   context: {},
-  sourcePort: number = 0
+  sourcePort: number = 0,
+  _debug: boolean,
+  deviceId: string
 ): Promise<void> {
   const [host, portStr] = address.split(":", 2);
   const port = portStr ? parseInt(portStr) : 80;
@@ -207,15 +220,15 @@ export async function udpConnectionRequest(
       .update(`${ts}${id}${username}${cn}`)
       .digest("hex");
     const uri = `http://${address}?ts=${ts}&id=${id}&un=${username}&cn=${cn}&sig=${sig}`;
-    const message = Buffer.from(
-      `GET ${uri} HTTP/1.1\r\nHost: ${address}\r\n\r\n`
-    );
+    const msg = `GET ${uri} HTTP/1.1\r\nHost: ${address}\r\n\r\n`;
+    const message = Buffer.from(msg);
 
     for (let i = 0; i < 3; ++i) {
       await new Promise((resolve, reject) => {
         client.send(message, 0, message.length, port, host, (err: Error) => {
           if (err) reject(err);
           else resolve();
+          if (_debug) debug.outgoingUdpMessage(host, deviceId, port, msg);
         });
       });
     }

lib/cwmp.ts

@@ -19,7 +19,6 @@
 
 import * as zlib from "zlib";
 import * as crypto from "crypto";
-import * as fs from "fs";
 import { Socket } from "net";
 import * as auth from "./auth";
 import * as config from "./config";
@@ -53,6 +52,7 @@ import { promisify } from "util";
 import { TLSSocket } from "tls";
 import { dependencies as DEPENDENCIES } from "../package.json";
 import { parseXmlDeclaration } from "./xml-parser";
+import * as debug from "./debug";
 
 const soap =
   DEPENDENCIES["libxmljs"] && config.get("XML_LIBXMLJS")
@@ -170,18 +170,6 @@ async function writeResponse(
   // Close connection after last request in session
   if (close) res.headers["Connection"] = "close";
 
-  if (sessionContext.debug) {
-    const dump =
-      `# RESPONSE ${new Date(Date.now())}\n` +
-      JSON.stringify(res.headers) +
-      "\n" +
-      res.data +
-      "\n\n";
-    fs.appendFile(`./debug/${sessionContext.deviceId}.dump`, dump, err => {
-      if (err) throw err;
-    });
-  }
-
   let data = res.data;
 
   // Respond using the same content-encoding as the request
@@ -200,9 +188,13 @@ async function writeResponse(
     }
   }
 
-  res.headers["Content-Length"] = data.length;
-  sessionContext.httpResponse.writeHead(res.code, res.headers);
-  sessionContext.httpResponse.end(data);
+  const httpResponse = sessionContext.httpResponse;
+  httpResponse.setHeader("Content-Length", Buffer.byteLength(data));
+  httpResponse.writeHead(res.code, res.headers);
+  httpResponse.end(data);
+
+  if (sessionContext.debug)
+    debug.outgoingHttpResponse(httpResponse, sessionContext.deviceId, res.data);
 
   if (sessionContext.httpRequest.connection.destroyed) {
     logger.accessError({
@@ -950,9 +942,14 @@ async function reportBadState(sessionContext: SessionContext): Promise<void> {
     message: "Bad session state",
     sessionContext: sessionContext
   });
-  currentSessions.delete(sessionContext.httpResponse.connection);
-  sessionContext.httpResponse.writeHead(400, { Connection: "close" });
-  sessionContext.httpResponse.end("Bad session state");
+  const httpResponse = sessionContext.httpResponse;
+  currentSessions.delete(httpResponse.connection);
+  const body = "Bad session state";
+  httpResponse.setHeader("Content-Length", Buffer.byteLength(body));
+  httpResponse.writeHead(400, { Connection: "close" });
+  httpResponse.end(body);
+  if (sessionContext.debug)
+    debug.outgoingHttpResponse(httpResponse, sessionContext.deviceId, body);
 }
 
 async function responseUnauthorized(
@@ -983,8 +980,13 @@ async function responseUnauthorized(
     currentSessions.set(sessionContext.httpRequest.connection, sessionContext);
   }
 
-  sessionContext.httpResponse.writeHead(401, resHeaders);
-  sessionContext.httpResponse.end("Unauthorized");
+  const httpResponse = sessionContext.httpResponse;
+  const body = "Unauthorized";
+  httpResponse.setHeader("Content-Length", Buffer.byteLength(body));
+  httpResponse.writeHead(401, resHeaders);
+  httpResponse.end(body);
+  if (sessionContext.debug)
+    debug.outgoingHttpResponse(httpResponse, sessionContext.deviceId, body);
 }
 
 async function processRequest(
@@ -1176,28 +1178,6 @@ async function listenerAsync(
   // Request aborted
   if (!body) return;
 
-  async function parsedRpc(sessionContext, rpc, parseWarnings): Promise<void> {
-    for (const w of parseWarnings) {
-      w.sessionContext = sessionContext;
-      w.rpc = rpc;
-      logger.accessWarn(w);
-    }
-
-    if (sessionContext.debug) {
-      const dump =
-        `# REQUEST ${new Date(Date.now())}\n` +
-        JSON.stringify(httpRequest.headers) +
-        "\n" +
-        body +
-        "\n\n";
-      fs.appendFile(`./debug/${sessionContext.deviceId}.dump`, dump, err => {
-        if (err) throw err;
-      });
-    }
-
-    return processRequest(sessionContext, rpc);
-  }
-
   const newConnection = !currentSessions.has(httpRequest.connection);
 
   const sessionContext = await getSession(httpRequest.connection, sessionId);
@@ -1214,8 +1194,18 @@ async function listenerAsync(
         sessionContext: sessionContext
       });
 
+      const _body = "Invalid session";
+      httpResponse.setHeader("Content-Length", Buffer.byteLength(_body));
       httpResponse.writeHead(400, { Connection: "close" });
-      httpResponse.end("Invalid session");
+      httpResponse.end(_body);
+      if (sessionContext.debug) {
+        debug.outgoingHttpResponse(
+          httpResponse,
+          sessionContext.deviceId,
+          _body
+        );
+      }
+
       return;
     }
   } else if (stats.concurrentRequests > MAX_CONCURRENT_REQUESTS) {
@@ -1242,6 +1232,19 @@ async function listenerAsync(
 
   const bodyStr = body.toString(charset);
 
+  async function parsedRpc(_sessionContext, rpc, parseWarnings): Promise<void> {
+    for (const w of parseWarnings) {
+      w.sessionContext = _sessionContext;
+      w.rpc = rpc;
+      logger.accessWarn(w);
+    }
+
+    if (_sessionContext.debug)
+      debug.incomingHttpRequest(httpRequest, _sessionContext.deviceId, bodyStr);
+
+    return processRequest(_sessionContext, rpc);
+  }
+
   const parseWarnings = [];
   let rpc;
   try {
@@ -1259,8 +1262,30 @@ async function listenerAsync(
         httpResponse: httpResponse
       }
     });
+    httpResponse.setHeader("Content-Length", Buffer.byteLength(error.message));
     httpResponse.writeHead(400, { Connection: "close" });
     httpResponse.end(error.message);
+    if (sessionContext) {
+      if (sessionContext.debug) {
+        debug.outgoingHttpResponse(
+          httpResponse,
+          sessionContext.deviceId,
+          error.message
+        );
+      }
+    } else {
+      const cacheSnapshot = await localCache.getCurrentSnapshot();
+      const d = !!localCache.getConfig(cacheSnapshot, "cwmp.debug", {
+        remoteAddress: httpResponse.connection.remoteAddress
+      });
+      if (d) {
+        debug.outgoingHttpResponse(
+          httpResponse,
+          sessionContext.deviceId,
+          error.message
+        );
+      }
+    }
     return;
   }
 
@@ -1284,8 +1309,17 @@ async function listenerAsync(
         httpResponse: httpResponse
       }
     });
+    const _body = "Invalid session";
+    httpResponse.setHeader("Content-Length", Buffer.byteLength(_body));
     httpResponse.writeHead(400, { Connection: "close" });
-    httpResponse.end("Invalid session");
+    httpResponse.end(_body);
+    const cacheSnapshot = await localCache.getCurrentSnapshot();
+    const d = !!localCache.getConfig(cacheSnapshot, "cwmp.debug", {
+      remoteAddress: httpResponse.connection.remoteAddress
+    });
+    if (d)
+      debug.outgoingHttpResponse(httpResponse, sessionContext.deviceId, _body);
+
     return;
   }
 
@@ -1298,7 +1332,8 @@ async function listenerAsync(
     id: deviceId,
     serialNumber: rpc.cpeRequest.deviceId["SerialNumber"],
     productClass: rpc.cpeRequest.deviceId["ProductClass"],
-    oui: rpc.cpeRequest.deviceId["OUI"]
+    oui: rpc.cpeRequest.deviceId["OUI"],
+    remoteAddress: httpRequest.connection.remoteAddress
   };
 
   const sessionTimeout =

lib/debug.ts

@@ -0,0 +1,204 @@
+/**
+ * Copyright 2013-2019  Zaid Abdulla
+ *
+ * This file is part of GenieACS.
+ *
+ * GenieACS is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU Affero General Public License as
+ * published by the Free Software Foundation, either version 3 of the
+ * License, or (at your option) any later version.
+ *
+ * GenieACS is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with GenieACS.  If not, see <http://www.gnu.org/licenses/>.
+ */
+
+import {
+  IncomingMessage,
+  ServerResponse,
+  ClientRequest,
+  RequestOptions
+} from "http";
+import { Socket } from "net";
+import { appendFileSync } from "fs";
+import * as yaml from "yaml";
+import * as config from "./config";
+
+const DEBUG_FILE = "" + config.get("DEBUG_FILE");
+const DEBUG_FORMAT = "" + config.get("DEBUG_FORMAT");
+
+const connectionTimestamps = new WeakMap<Socket, Date>();
+
+function getConnectionTimestamp(connection: Socket): Date {
+  let t = connectionTimestamps.get(connection);
+  if (!t) {
+    t = new Date();
+    connectionTimestamps.set(connection, t);
+  }
+  return t;
+}
+
+export function incomingHttpRequest(
+  httpRequest: IncomingMessage,
+  deviceId: string,
+  body: string
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const con = httpRequest.connection;
+  const msg = {
+    event: "incoming HTTP request",
+    timestamp: now,
+    remoteAddress: con.remoteAddress,
+    deviceId: deviceId,
+    connection: getConnectionTimestamp(con),
+    localPort: con.localPort,
+    method: httpRequest.method,
+    url: httpRequest.url,
+    headers: httpRequest.headers,
+    body: body
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}
+
+export function outgoingHttpResponse(
+  httpResponse: ServerResponse,
+  deviceId: string,
+  body: string
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const con = httpResponse.connection;
+  const msg = {
+    event: "outgoing HTTP response",
+    timestamp: now,
+    remoteAddress: con.remoteAddress,
+    deviceId: deviceId,
+    connection: getConnectionTimestamp(con),
+    statusCode: httpResponse.statusCode,
+    headers: httpResponse.getHeaders(),
+    body: body
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}
+
+export function outgoingHttpRequest(
+  httpRequest: ClientRequest,
+  deviceId: string,
+  options: RequestOptions,
+  body: string
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const con = httpRequest.connection;
+  const msg = {
+    event: "outgoing HTTP request",
+    timestamp: now,
+    remoteAddress: con.remoteAddress,
+    deviceId: deviceId,
+    connection: getConnectionTimestamp(con),
+    remotePort: options.port,
+    method: options.method || "GET",
+    url: options.path,
+    headers: httpRequest.getHeaders(),
+    body: body
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}
+
+export function outgoingHttpRequestError(
+  httpRequest: ClientRequest,
+  deviceId: string,
+  options: RequestOptions,
+  err: Error
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const msg = {
+    event: "outgoing HTTP request",
+    timestamp: now,
+    remoteAddress: options.hostname,
+    deviceId: deviceId,
+    connection: null,
+    remotePort: options.port,
+    method: options.method,
+    url: options.path,
+    headers: httpRequest.getHeaders(),
+    error: err.message
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}
+
+export function incomingHttpResponse(
+  httpResponse: IncomingMessage,
+  deviceId: string,
+  body: string
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const con = httpResponse.connection;
+  const msg = {
+    event: "incoming HTTP response",
+    timestamp: now,
+    remoteAddress: con.remoteAddress,
+    deviceId: deviceId,
+    connection: getConnectionTimestamp(httpResponse.connection),
+    statusCode: httpResponse.statusCode,
+    headers: httpResponse.headers,
+    body: body
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}
+
+export function outgoingUdpMessage(
+  remoteAddress: string,
+  deviceId: string,
+  remotePort: number,
+  body: string
+): void {
+  if (!DEBUG_FILE) return;
+  const now = new Date();
+  const msg = {
+    event: "outgoing UDP message",
+    timestamp: now,
+    remoteAddress: remoteAddress,
+    deviceId: deviceId,
+    remotePort: remotePort,
+    body: body
+  };
+
+  if (DEBUG_FORMAT === "yaml")
+    appendFileSync(DEBUG_FILE, "---\n" + yaml.stringify(msg));
+  else if (DEBUG_FORMAT === "json")
+    appendFileSync(DEBUG_FILE, JSON.stringify(msg) + "\n");
+  else throw new Error(`Unrecognized DEBUG_FORMAT option`);
+}

package.json

@@ -31,7 +31,8 @@
     "libxmljs": "^0.19.5",
     "mongodb": "^3.1.13",
     "parsimmon": "^1.12.0",
-    "seedrandom": "^2.4.4"
+    "seedrandom": "^2.4.4",
+    "yaml": "^1.3.2"
   },
   "devDependencies": {
     "@types/jsonwebtoken": "^8.3.0",
@@ -62,8 +63,7 @@
     "rollup-plugin-typescript": "^1.0.0",
     "ts-node": "^8.0.2",
     "typescript": "^3.3.3",
-    "webpack": "^4.29.5",
-    "yaml": "^1.3.2"
+    "webpack": "^4.29.5"
   },
   "engines": {
     "node": ">=8.14.0"