Use debug package for logging

package.json

@@ -7,6 +7,7 @@
   "dependencies": {
     "compression": "^1.7.3",
     "date-fns": "^1.30.1",
+    "debug": "^4.1.1",
     "dotenv": "^7.0.0",
     "express": "^4.16.4",
     "iconv-lite": "^0.4.24",
@@ -14,7 +15,8 @@
     "multiparty": "^4.2.1",
     "pg": "^7.10.0",
     "raw-body": "^2.3.3",
-    "sql-bricks-postgres": "^0.5.0"
+    "sql-bricks-postgres": "^0.5.0",
+    "supports-color": "^7.1.0"
   },
   "scripts": {
     "build": "tsc",
@@ -23,6 +25,7 @@
   },
   "devDependencies": {
     "@types/compression": "^0.0.36",
+    "@types/debug": "^4.1.5",
     "@types/dotenv": "^6.1.1",
     "@types/express": "^4.16.1",
     "@types/jest": "^24.0.11",

src/aimedb/decoder.ts

@@ -1,7 +1,10 @@
+import logger from "debug";
 import { Transform } from "stream";
 
 import * as Request from "./request";
 
+const debug = logger("app:aimedb:decoder");
+
 function begin(msg: Buffer): Request.AimeRequestBase {
   const gameId = msg.toString("ascii", 0x000a, 0x000e);
   const keychipId = msg.toString("ascii", 0x0014, 0x001f);
@@ -116,6 +119,10 @@ export class Decoder extends Transform {
       );
     }
 
-    return callback(null, reader(msg));
+    const obj = reader(msg);
+
+    debug(`Decode ${JSON.stringify(obj)}`);
+
+    return callback(null, obj);
   }
 }

src/aimedb/encoder.ts

@@ -1,7 +1,10 @@
+import logger from "debug";
 import { Transform } from "stream";
 
 import { AimeResponse, RegisterLevel } from "./response";
 
+const debug = logger("app:aimedb:encoder");
+
 const registerLevels = new Map<RegisterLevel, number>();
 
 registerLevels.set("none", 0);
@@ -27,7 +30,7 @@ export class Encoder extends Transform {
   }
 
   _transform(msg: AimeResponse, encoding, callback) {
-    console.log("Aimedb: Encode", msg);
+    debug(`Encode ${JSON.stringify(msg)}`);
 
     let buf: Buffer;
 
@@ -105,7 +108,7 @@ export class Encoder extends Transform {
         return callback(new Error("Unimplemented response type"));
     }
 
-    console.log("Aimedb: Send", buf.toString("hex"));
+    debug(`Send ${buf.toString("hex")}`);
 
     return callback(null, buf);
   }

src/aimedb/frame.ts

@@ -1,5 +1,8 @@
+import logger from "debug";
 import { Transform } from "stream";
 
+const debug = logger("app:aimedb:frame");
+
 export class Deframer extends Transform {
   private state: Buffer;
 
@@ -33,7 +36,7 @@ export class Deframer extends Transform {
 
     const frame = this.state.slice(0, len);
 
-    console.log("Aimedb: Recv", frame.toString("hex"));
+    debug(`Recv ${frame.toString("hex")}`);
 
     this.state = this.state.slice(len);
 

src/aimedb/handler.ts

@@ -1,13 +1,17 @@
+import logger from "debug";
+
 import { Repositories } from "./repo";
 import * as Req from "./request";
 import * as Res from "./response";
 
+const debug = logger("app:aimedb:ops");
+
 function hello(
   rep: Repositories,
   req: Req.HelloRequest,
   now: Date
 ): Res.HelloResponse {
-  console.log("Aimedb: Hello");
+  debug("Hello");
 
   return { type: req.type, status: 1 };
 }
@@ -17,7 +21,7 @@ function campaign(
   req: Req.CampaignRequest,
   now: Date
 ): Res.CampaignResponse {
-  console.log("Aimedb: Campaign stuff");
+  debug("Campaign stuff");
 
   return { type: req.type, status: 1 };
 }
@@ -27,7 +31,7 @@ function feliCaLookup(
   req: Req.FeliCaLookupRequest,
   now: Date
 ): Res.FeliCaLookupResponse {
-  console.log("Aimedb: FeliCa access code lookup");
+  debug("FeliCa access code lookup");
 
   // Well, this access code transformation is the million dollar question eh
   // Return a decimal representation for now.
@@ -47,7 +51,7 @@ async function lookup(
   req: Req.LookupRequest,
   now: Date
 ): Promise<Res.LookupResponse> {
-  console.log("Aimedb: Mifare lookup v1", req.luid);
+  debug(`Mifare lookup v1: luid=${req.luid}`);
 
   return {
     type: req.type,
@@ -62,7 +66,7 @@ async function lookup2(
   req: Req.LookupRequest2,
   now: Date
 ): Promise<Res.LookupResponse2> {
-  console.log("Aimedb: Mifare lookup v2", req.luid);
+  debug(`Mifare lookup v2: luid=${req.luid}`);
 
   return {
     type: req.type,
@@ -77,7 +81,7 @@ async function register(
   req: Req.RegisterRequest,
   now: Date
 ): Promise<Res.RegisterResponse> {
-  console.log("Aimedb: Mifare register", req.luid);
+  debug(`User register: luid=${req.luid}`);
 
   return {
     type: req.type,
@@ -91,7 +95,7 @@ function log(
   req: Req.LogRequest,
   now: Date
 ): Res.LogResponse {
-  console.log("Aimedb: Log message");
+  debug("Log message");
 
   return { type: req.type, status: 1 };
 }
@@ -124,7 +128,7 @@ export async function dispatch(
       return log(rep, req, now);
 
     case "goodbye":
-      console.log("Aimedb: Goodbye");
+      debug("Goodbye");
 
       return undefined;
 

src/aimedb/index.ts

@@ -1,3 +1,4 @@
+import logger from "debug";
 import { Socket } from "net";
 
 import { dispatch } from "./handler";
@@ -5,22 +6,22 @@ import { AimeRequest } from "./request";
 import { setup } from "./pipeline";
 import { beginDbSession } from "./db";
 
+const debug = logger("app:aimedb:session");
+
 export default async function aimedb(socket: Socket) {
-  console.log("Aimedb: Connection opened");
+  debug("Connection opened");
 
   const { input, output } = setup(socket);
   const txn = await beginDbSession();
 
   try {
     for await (const obj of input) {
-      console.log("Aimedb: Decode", obj);
-
       const now = new Date();
       const req = obj as AimeRequest;
       const res = await dispatch(txn, req, now);
 
       if (res === undefined) {
-        console.log("Aimedb: Closing connection");
+        debug("Closing connection");
 
         break;
       }
@@ -30,10 +31,10 @@ export default async function aimedb(socket: Socket) {
 
     await txn.commit();
   } catch (e) {
-    console.log("Aimedb: Connection error:\n", e);
+    debug(`Connection error:\n${e.toString()}\n`);
     await txn.rollback();
   }
 
-  console.log("Aimedb: Connection closed\n");
+  debug("Connection closed");
   socket.end();
 }

src/allnet.ts

@@ -1,11 +1,13 @@
 import addHours from "date-fns/add_hours";
 import express from "express";
 import iconv from "iconv-lite";
+import logger from "debug";
 import read from "raw-body";
 import { unzipSync } from "zlib";
 
 import { startupHost, startupUri } from "./switchboard";
 
+const debug = logger("app:allnet");
 const hourDelta = parseInt(process.env.HOUR_DELTA || "0");
 const app = express();
 
@@ -58,7 +60,7 @@ app.use("/sys/servlet/PowerOn", async function(req, res, next) {
 });
 
 app.post("/sys/servlet/PowerOn", function(req, resp) {
-  console.log("--- Startup Request ---\n\n", req.body);
+  debug("--- Startup Request ---\n\n", req.body);
 
   // Cut milliseconds out of ISO timestamp
 
@@ -89,8 +91,8 @@ app.post("/sys/servlet/PowerOn", function(req, resp) {
     token: req.body.token,
   };
 
-  console.log("\n--- Startup Response ---\n\n", resParams);
-  console.log("");
+  debug("\n--- Startup Response ---\n\n", resParams);
+  debug("");
 
   resp.send(resParams);
 });

src/billing.ts

@@ -1,5 +1,6 @@
-import read from "raw-body";
 import express from "express";
+import logger from "debug";
+import read from "raw-body";
 
 import { createSign } from "crypto";
 import { inflateRawSync } from "zlib";
@@ -9,6 +10,7 @@ interface Kvps {
   [key: string]: string;
 }
 
+const debug = logger("app:billing");
 const billingKeyPair = readFileSync("pki/billing.key");
 
 // nearfull: high 16 bits is billing mode, low 16 bits is actual nearfull val.
@@ -60,7 +62,7 @@ app.use(async function(req, res, next) {
 });
 
 app.post("/request/", function(req, res) {
-  console.log("--- Billing Request ---\n\n", req.body);
+  debug("--- Billing Request ---\n\n", req.body);
 
   const first = req.body[0];
 
@@ -133,8 +135,8 @@ app.post("/request/", function(req, res) {
     playhistory: "000000/0:000000/0:000000/0",
   });
 
-  console.log("\n--- Billing Response ---\n\n", resItems);
-  console.log("");
+  debug("\n--- Billing Response ---\n\n", resItems);
+  debug("");
 
   res.set("content-type", "text/plain");
   res.send(resItems);

src/chunithm.ts

@@ -1,6 +1,8 @@
 import compression from "compression";
 import express from "express";
+import logger from "debug";
 
+const debug = logger("app:chuni:io");
 const app = express();
 
 // Thankfully we can use standard middleware for JSON I/O. We have to use a
@@ -27,13 +29,13 @@ app.use(express.json());
 // Trace requests and responses
 
 app.use(function(req, resp, next) {
-  console.log("\n--- Chunithm %s ---\n", req.url);
-  console.log("Request:", req.body);
+  debug(`\n--- Chunithm ${req.url} ---\n`);
+  debug(`Request: ${JSON.stringify(req.body)}\n`);
 
   const prevJson = resp.json;
 
   resp.json = function(obj) {
-    console.log("Response:", obj);
+    debug(`Response: ${JSON.stringify(obj)}`);
 
     resp.json = prevJson;
     resp.json.apply(this, arguments);

src/db.ts

@@ -1,8 +1,10 @@
 import { randomBytes } from "crypto";
+import logger from "debug";
 import { Pool, PoolClient } from "pg";
 
 export type Id<T> = bigint & { __id: T };
 
+const debug = logger("app:sql");
 const currentSchemaVer = 3;
 
 const pool = new Pool();
@@ -49,7 +51,7 @@ async function testConnection(): Promise<void> {
       );
     }
 
-    console.log("SQL DB: Connection established");
+    debug("Connection established");
   } finally {
     conn.release();
   }

src/diva.ts

@@ -1,9 +1,11 @@
 import express from "express";
+import logger from "debug";
 import read from "raw-body";
 
 import { Form } from "multiparty";
 import { inflateSync } from "zlib";
 
+const debug = logger("app:diva:io");
 const app = express();
 
 //
@@ -14,7 +16,7 @@ app.use(async function(req, res, next) {
   const send_ = res.send;
 
   res.send = function(kvps) {
-    console.log("Response:", kvps);
+    debug(`Response: ${JSON.stringify(kvps)}\n`);
 
     const bits: string[] = [];
 
@@ -56,8 +58,8 @@ app.use(async function(req, res, next) {
 
     req.body = body;
 
-    console.log("\n--- Diva ---\n");
-    console.log("Request:", req.body);
+    debug("\n--- Diva ---\n");
+    debug(`Request: ${JSON.stringify(req.body)}\n`);
 
     return next();
   } else if (req.is("multipart/form-data")) {
@@ -70,8 +72,8 @@ app.use(async function(req, res, next) {
 
       req.body = { ...files, ...fields };
 
-      console.log("\n--- Diva (Multipart) ---\n");
-      console.log("Request:", req.body);
+      debug("\n--- Diva (Multipart) ---\n");
+      debug(`Request: ${JSON.stringify(req.body)}\n`);
 
       return next();
     });

src/idz/db/teamReservation.ts

@@ -99,8 +99,6 @@ export class SqlTeamReservationRepository
       throw new Error(`Reservation not found for Aime ID ${aimeId}`);
     }
 
-    console.log(row);
-
     const insertSql = sql
       .insert("idz.team_member", {
         id: row.profile_id,

src/idz/decoder/index.ts

@@ -1,3 +1,4 @@
+import logger from "debug";
 import { Transform } from "stream";
 
 import { checkTeamName } from "./checkTeamName";
@@ -49,6 +50,8 @@ import { updateUiReport } from "./updateUiReport";
 import { updateUserLog } from "./updateUserLog";
 import { lockProfileExtend } from "./lockProfileExtend";
 
+const debug = logger("app:idz:decoder");
+
 export type ReaderFn = ((buf: Buffer) => Request) & {
   msgCode: number;
   msgLen: number;
@@ -181,8 +184,8 @@ export class Decoder extends Transform {
     const reqBuf = this.state.slice(0, 0x30 + msgLen);
     const payloadBuf = reqBuf.slice(0x30);
 
-    console.log("Idz: Req: Raw:", reqBuf.toString("hex"));
-    console.log("Idz: Req: Header:", header);
+    debug(`Raw: ${reqBuf.toString("hex")}`);
+    debug(`Header: ${JSON.stringify(header)}`);
 
     const reader = readerFns.get(msgCode);
 
@@ -194,7 +197,7 @@ export class Decoder extends Transform {
 
     const payload = reader(payloadBuf);
 
-    console.log("Idz: Req: Payload:", payload);
+    debug(`Payload: ${JSON.stringify(payload)}`);
 
     return callback(null, payload);
   }

src/idz/decoder/saveSettings.ts

@@ -7,8 +7,6 @@ saveSettings.msgLen = 0x0020;
 export function saveSettings(buf: Buffer): SaveSettingsRequest {
   const pack = buf.readUInt32LE(0x000c);
 
-  console.log("Idz: SETTINGS PACK", pack.toString(16));
-
   return {
     type: "save_settings_req",
     aimeId: buf.readUInt32LE(0x0004) as AimeId,

src/idz/encoder/index.ts

@@ -1,3 +1,4 @@
+import logger from "debug";
 import { Transform } from "stream";
 
 import { _team } from "./_team";
@@ -33,6 +34,8 @@ import { updateTeamLeader } from "./updateTeamLeader";
 import { updateTeamMember } from "./updateTeamMember";
 import { Response } from "../response";
 
+const debug = logger("app:idz:encoder");
+
 function encode(res: Response): Buffer {
   switch (res.type) {
     case "check_team_name_res":
@@ -147,14 +150,14 @@ export class Encoder extends Transform {
   }
 
   _transform(res: Response, encoding, callback) {
-    console.log("Idz: Res: Object:", res);
+    debug(`Object: ${JSON.stringify(res)}`);
 
     const buf = encode(res);
 
-    console.log("Idz: Res: Encoded:", buf.toString("hex"));
+    debug(`Encoded: ${buf.toString("hex")}`);
 
     if (buf.readInt16LE(0) === 0) {
-      throw new Error("MESSAGE TYPE CODE YOU FUCKING IDIOT");
+      throw new Error("Missing message type code");
     }
 
     return callback(null, buf);

src/idz/handler/createAutoTeam.ts

@@ -59,8 +59,6 @@ export async function createAutoTeam(
     const [lastAuto, lastTeamId] = peek;
     const occupancy = await w.teamReservations().occupancyHack(lastTeamId);
 
-    console.log(occupancy);
-
     if (occupancy < 6) {
       // Team isn't full, so return this one
       await w.teamReservations().reserveHack(lastTeamId, aimeId, now);

src/idz/handler/loadTopTen.ts

@@ -50,8 +50,6 @@ export async function loadTopTen(
     });
   }
 
-  console.log(JSON.stringify(courses));
-
   return {
     type: "load_top_ten_res",
     courseCount: courses.length,

src/idz/index.ts

@@ -1,14 +1,17 @@
+import logger from "debug";
 import { Socket } from "net";
 
 import { beginDbSession } from "./db";
 import { dispatch } from "./handler";
 import { setup } from "./setup";
 
+const debug = logger("app:idz:session");
+
 export default async function idz(socket: Socket) {
   const txn = await beginDbSession();
   const { input, output } = setup(socket);
 
-  console.log("Idz: Connection opened");
+  debug("Connection opened");
 
   try {
     for await (const req of input) {
@@ -17,11 +20,11 @@ export default async function idz(socket: Socket) {
 
     await txn.commit();
   } catch (e) {
-    console.log("Idz: Error:", e);
+    debug(`Error:\n${e.toString()}`);
     await txn.rollback();
   }
 
-  console.log("Idz: Connection closed\n");
+  debug("Connection closed");
 
   input.end();
 }

src/idz/ping.ts

@@ -1,11 +1,14 @@
+import logger from "debug";
 import { createSocket } from "dgram";
 
+const debug = logger("app:idz:ping");
+
 export default function createPing(port: number, host: string) {
   const socket = createSocket("udp4");
 
   socket.bind(port, host);
   socket.on("message", (msg, rinfo) => {
-    console.log(`Idz Ping: Ping from ${rinfo.address}:${rinfo.port}`);
+    debug(`Ping from ${rinfo.address}:${rinfo.port}`);
     socket.send(msg, rinfo.port, rinfo.address);
   });
 }

src/switchboard.ts

@@ -1,5 +1,7 @@
+import logger from "debug";
 import * as os from "os";
 
+const debug = logger("app:switchboard");
 const cfgHostExt: string | undefined = process.env.HOST_EXT;
 const cfgHostInt: string | undefined = process.env.HOST_INT;
 
@@ -72,13 +74,9 @@ export function startupUri(model: string): string {
 // Diagnostic dump
 //
 
-console.log(
-  `Switchboard: HOST_EXT: ${HOST_EXT} (Service host name sent to clients)`
-);
-console.log(`Switchboard: HOST_INT: ${HOST_INT} (Bind address)`);
+debug(`HOST_EXT: ${HOST_EXT} (Service host name sent to clients)`);
+debug(`HOST_INT: ${HOST_INT} (Bind address)`);
 
 if (cfgHostExt === undefined || cfgHostInt === undefined) {
-  console.log(
-    "Switchboard: Warning: Check .env and env vars! Using unreliable fallback."
-  );
+  debug("Warning: Check .env and env vars! Using unreliable fallback.");
 }

yarn.lock

@@ -331,6 +331,11 @@
   dependencies:
     "@types/node" "*"
 
+"@types/debug@^4.1.5":
+  version "4.1.5"
+  resolved "https://registry.yarnpkg.com/@types/debug/-/debug-4.1.5.tgz#b14efa8852b7768d898906613c23f688713e02cd"
+  integrity sha512-Q1y515GcOdTHgagaVFhHnIFQ38ygs/kmxdNpvpou+raI9UO3YZcHDngBSYKQklcKlvA7iuQlmIKbzvmxcOE9CQ==
+
 "@types/dotenv@^6.1.1":
   version "6.1.1"
   resolved "https://registry.yarnpkg.com/@types/dotenv/-/dotenv-6.1.1.tgz#f7ce1cc4fe34f0a4373ba99fefa437b0bec54b46"
@@ -1552,6 +1557,11 @@ has-flag@^3.0.0:
   resolved "https://registry.yarnpkg.com/has-flag/-/has-flag-3.0.0.tgz#b5d454dc2199ae225699f3467e5a07f3b955bafd"
   integrity sha1-tdRU3CGZriJWmfNGfloH87lVuv0=
 
+has-flag@^4.0.0:
+  version "4.0.0"
+  resolved "https://registry.yarnpkg.com/has-flag/-/has-flag-4.0.0.tgz#944771fd9c81c81265c4d6941860da06bb59479b"
+  integrity sha512-EykJT/Q1KjTWctppgIAgfSO0tKVuZUjhgMr17kqTumMl6Afv3EISleU7qZUzoXDFTAHTDC4NOoG/ZxU3EvlMPQ==
+
 has-symbols@^1.0.0:
   version "1.0.0"
   resolved "https://registry.yarnpkg.com/has-symbols/-/has-symbols-1.0.0.tgz#ba1a8f1af2a0fc39650f5c850367704122063b44"
@@ -3709,6 +3719,13 @@ supports-color@^6.0.0, supports-color@^6.1.0:
   dependencies:
     has-flag "^3.0.0"
 
+supports-color@^7.1.0:
+  version "7.1.0"
+  resolved "https://registry.yarnpkg.com/supports-color/-/supports-color-7.1.0.tgz#68e32591df73e25ad1c4b49108a2ec507962bfd1"
+  integrity sha512-oRSIpR8pxT1Wr2FquTNnGet79b3BWljqOuoW/h4oBhxJ/HUbX5nX6JSruTkvXDCFMwDPvsaTTbvMLKZWSy0R5g==
+  dependencies:
+    has-flag "^4.0.0"
+
 symbol-tree@^3.2.2:
   version "3.2.2"
   resolved "https://registry.yarnpkg.com/symbol-tree/-/symbol-tree-3.2.2.tgz#ae27db38f660a7ae2e1c3b7d1bc290819b8519e6"