Merge pull request #128 from AikidoSec/verbose-logging

README.md

@@ -82,11 +82,19 @@ You can control the output from Aikido Safe Chain using the `--safe-chain-loggin
 
 - `--safe-chain-logging=silent` - Suppresses all Aikido Safe Chain output except when malware is blocked. The package manager output is written to stdout as normal, and Safe Chain only writes a short message if it has blocked malware and causes the process to exit.
 
-Example usage:
+  Example usage:
 
-```shell
+  ```shell
-npm install express --safe-chain-logging=silent
+  npm install express --safe-chain-logging=silent
-```
+  ```
+
+- `--safe-chain-logging=verbose` - Enables detailed diagnostic output from Aikido Safe Chain. Useful for troubleshooting issues or understanding what Safe Chain is doing behind the scenes.
+
+  Example usage:
+
+  ```shell
+  npm install express --safe-chain-logging=verbose
+  ```
 
 # Usage in CI/CD
 

package.json

@@ -9,7 +9,8 @@
   "scripts": {
     "test": "npm run test --workspace=packages/safe-chain --workspace=packages/safe-chain-bun",
     "test:e2e": "npm run test --workspace=test/e2e",
-    "lint": "npm run lint --workspace=packages/safe-chain"
+    "lint": "npm run lint --workspace=packages/safe-chain",
+    "typecheck": "npm run typecheck --workspace=packages/safe-chain"
   },
   "repository": {
     "type": "git",

packages/safe-chain/src/config/settings.js

@@ -7,8 +7,13 @@ export function getLoggingLevel() {
     return LOGGING_SILENT;
   }
 
+  if (level === LOGGING_VERBOSE) {
+    return LOGGING_VERBOSE;
+  }
+
   return LOGGING_NORMAL;
 }
 
 export const LOGGING_SILENT = "silent";
 export const LOGGING_NORMAL = "normal";
+export const LOGGING_VERBOSE = "verbose";

packages/safe-chain/src/environment/userInteraction.js

@@ -2,12 +2,28 @@
 import chalk from "chalk";
 import ora from "ora";
 import { isCi } from "./environment.js";
-import { getLoggingLevel, LOGGING_SILENT } from "../config/settings.js";
+import {
+  getLoggingLevel,
+  LOGGING_SILENT,
+  LOGGING_VERBOSE,
+} from "../config/settings.js";
+
+/**
+ * @type {{ bufferOutput: boolean, bufferedMessages:(() => void)[]}}
+ */
+const state = {
+  bufferOutput: false,
+  bufferedMessages: [],
+};
 
 function isSilentMode() {
   return getLoggingLevel() === LOGGING_SILENT;
 }
 
+function isVerboseMode() {
+  return getLoggingLevel() === LOGGING_VERBOSE;
+}
+
 function emptyLine() {
   if (isSilentMode()) return;
 
@@ -22,7 +38,7 @@ function emptyLine() {
 function writeInformation(message, ...optionalParams) {
   if (isSilentMode()) return;
 
-  console.log(message, ...optionalParams);
+  writeOrBuffer(() => console.log(message, ...optionalParams));
 }
 
 /**
@@ -36,7 +52,7 @@ function writeWarning(message, ...optionalParams) {
   if (!isCi()) {
     message = chalk.yellow(message);
   }
-  console.warn(message, ...optionalParams);
+  writeOrBuffer(() => console.warn(message, ...optionalParams));
 }
 
 /**
@@ -48,7 +64,7 @@ function writeError(message, ...optionalParams) {
   if (!isCi()) {
     message = chalk.red(message);
   }
-  console.error(message, ...optionalParams);
+  writeOrBuffer(() => console.error(message, ...optionalParams));
 }
 
 function writeExitWithoutInstallingMaliciousPackages() {
@@ -56,7 +72,30 @@ function writeExitWithoutInstallingMaliciousPackages() {
   if (!isCi()) {
     message = chalk.red(message);
   }
-  console.error(message);
+  writeOrBuffer(() => console.error(message));
+}
+
+/**
+ * @param {string} message
+ * @param {...any} optionalParams
+ * @returns {void}
+ */
+function writeVerbose(message, ...optionalParams) {
+  if (!isVerboseMode()) return;
+
+  writeOrBuffer(() => console.log(message, ...optionalParams));
+}
+
+/**
+ *
+ * @param {() => void} messageFunction
+ */
+function writeOrBuffer(messageFunction) {
+  if (state.bufferOutput) {
+    state.bufferedMessages.push(messageFunction);
+  } else {
+    messageFunction();
+  }
 }
 
 /**
@@ -114,11 +153,27 @@ function startProcess(message) {
   }
 }
 
+function startBufferingLogs() {
+  state.bufferOutput = true;
+  state.bufferedMessages = [];
+}
+
+function writeBufferedLogsAndStopBuffering() {
+  state.bufferOutput = false;
+  for (const log of state.bufferedMessages) {
+    log();
+  }
+  state.bufferedMessages = [];
+}
+
 export const ui = {
+  writeVerbose,
   writeInformation,
   writeWarning,
   writeError,
   writeExitWithoutInstallingMaliciousPackages,
   emptyLine,
   startProcess,
+  startBufferingLogs,
+  writeBufferedLogsAndStopBuffering,
 };

packages/safe-chain/src/main.js

@@ -12,13 +12,15 @@ import chalk from "chalk";
  * @returns {Promise<number | never[]>}
  */
 export async function main(args) {
+  process.on("SIGINT", handleProcessTermination);
+  process.on("SIGTERM", handleProcessTermination);
+
   const proxy = createSafeChainProxy();
   await proxy.startServer();
 
   // Global error handlers to log unhandled errors
   process.on("uncaughtException", (error) => {
     ui.writeError(`Safe-chain: Uncaught exception: ${error.message}`);
-    // @ts-expect-error writeVerbose will be added in a future PR
     ui.writeVerbose(`Stack trace: ${error.stack}`);
     process.exit(1);
   });
@@ -26,7 +28,6 @@ export async function main(args) {
   process.on("unhandledRejection", (reason) => {
     ui.writeError(`Safe-chain: Unhandled promise rejection: ${reason}`);
     if (reason instanceof Error) {
-      // @ts-expect-error writeVerbose will be added in a future PR
       ui.writeVerbose(`Stack trace: ${reason.stack}`);
     }
     process.exit(1);
@@ -46,8 +47,16 @@ export async function main(args) {
       }
     }
 
+    // Buffer logs during package manager execution, this avoids interleaving
+    //  of logs from the package manager and safe-chain
+    // Not doing this could cause bugs to disappear when cursor movement codes
+    //  are written by the package manager while safe-chain is writing logs
+    ui.startBufferingLogs();
     const packageManagerResult = await getPackageManager().runCommand(args);
 
+    // Write all buffered logs
+    ui.writeBufferedLogsAndStopBuffering();
+
     if (!proxy.verifyNoMaliciousPackages()) {
       return 1;
     }
@@ -72,3 +81,7 @@ export async function main(args) {
     await proxy.stopServer();
   }
 }
+
+function handleProcessTermination() {
+  ui.writeBufferedLogsAndStopBuffering();
+}

packages/safe-chain/src/registryProxy/mitmRequestHandler.js

@@ -9,9 +9,13 @@ import { ui } from "../environment/userInteraction.js";
  * @param {(target: string) => Promise<boolean>} isAllowed
  */
 export function mitmConnect(req, clientSocket, isAllowed) {
+  ui.writeVerbose(`Safe-chain: Set up MITM tunnel for ${req.url}`);
   const { hostname } = new URL(`http://${req.url}`);
 
-  clientSocket.on("error", () => {
+  clientSocket.on("error", (err) => {
+    ui.writeVerbose(
+      `Safe-chain: Client socket error for ${req.url}: ${err.message}`
+    );
     // NO-OP
     // This can happen if the client TCP socket sends RST instead of FIN.
     // Not subscribing to 'close' event will cause node to throw and crash.
@@ -56,6 +60,7 @@ function createHttpsServer(hostname, isAllowed) {
     const targetUrl = `https://${hostname}${pathAndQuery}`;
 
     if (!(await isAllowed(targetUrl))) {
+      ui.writeVerbose(`Safe-chain: Blocking request to ${targetUrl}`);
       res.writeHead(403, "Forbidden - blocked by safe-chain");
       res.end("Blocked by safe-chain");
       return;
@@ -96,7 +101,10 @@ function getRequestPathAndQuery(url) {
 function forwardRequest(req, hostname, res) {
   const proxyReq = createProxyRequest(hostname, req, res);
 
-  proxyReq.on("error", () => {
+  proxyReq.on("error", (err) => {
+    ui.writeVerbose(
+      `Safe-chain: Error occurred while proxying request: ${err.message}`
+    );
     res.writeHead(502);
     res.end("Bad Gateway");
   });
@@ -111,6 +119,9 @@ function forwardRequest(req, hostname, res) {
   });
 
   req.on("end", () => {
+    ui.writeVerbose(
+      `Safe-chain: Finished proxying request to ${req.url} for ${hostname}`
+    );
     proxyReq.end();
   });
 }

packages/safe-chain/src/registryProxy/registryProxy.js

@@ -138,6 +138,7 @@ function handleConnect(req, clientSocket, head) {
     mitmConnect(req, clientSocket, isAllowedUrl);
   } else {
     // For other hosts, just tunnel the request to the destination tcp socket
+    ui.writeVerbose(`Safe-chain: Tunneling request to ${req.url}`);
     tunnelRequest(req, clientSocket, head);
   }
 }

packages/safe-chain/src/scanning/audit/index.js

@@ -1,3 +1,4 @@
+import { ui } from "../../environment/userInteraction.js";
 import {
   MALWARE_STATUS_MALWARE,
   openMalwareDatabase,
@@ -38,8 +39,14 @@ export async function auditChanges(changes) {
     );
 
     if (malwarePackage) {
+      ui.writeVerbose(
+        `Safe-chain: Package ${change.name}@${change.version} is marked as malware: ${malwarePackage.status}`
+      );
       disallowedChanges.push({ ...change, reason: malwarePackage.status });
     } else {
+      ui.writeVerbose(
+        `Safe-chain: Package ${change.name}@${change.version} is clean`
+      );
       allowedChanges.push(change);
     }
   }