Add verbose logging setting + setup buffering of logs to prevent interleaving logs with the package manager.

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,25 @@
 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";
+
+const state = {
+  bufferOutput: false,
+  bufferedMessages: [],
+};
 
 function isSilentMode() {
   return getLoggingLevel() === LOGGING_SILENT;
 }
 
+function isVerboseMode() {
+  return getLoggingLevel() === LOGGING_VERBOSE;
+}
+
 function emptyLine() {
   if (isSilentMode()) return;
 
@@ -17,7 +30,7 @@ function emptyLine() {
 function writeInformation(message, ...optionalParams) {
   if (isSilentMode()) return;
 
-  console.log(message, ...optionalParams);
+  writeOrBuffer(() => console.log(message, ...optionalParams));
 }
 
 function writeWarning(message, ...optionalParams) {
@@ -26,14 +39,14 @@ function writeWarning(message, ...optionalParams) {
   if (!isCi()) {
     message = chalk.yellow(message);
   }
-  console.warn(message, ...optionalParams);
+  writeOrBuffer(() => console.warn(message, ...optionalParams));
 }
 
 function writeError(message, ...optionalParams) {
   if (!isCi()) {
     message = chalk.red(message);
   }
-  console.error(message, ...optionalParams);
+  writeOrBuffer(() => console.error(message, ...optionalParams));
 }
 
 function writeExitWithoutInstallingMaliciousPackages() {
@@ -41,12 +54,21 @@ function writeExitWithoutInstallingMaliciousPackages() {
   if (!isCi()) {
     message = chalk.red(message);
   }
-  console.error(message);
+  writeOrBuffer(() => console.error(message));
 }
 
 function writeVerboseInformation(message, ...optionalParams) {
-  // TODO: Correctly implement verbose logging
-  writeInformation(message, ...optionalParams);
+  if (!isVerboseMode()) return;
+
+  writeOrBuffer(() => console.log(message, ...optionalParams));
+}
+
+function writeOrBuffer(messageFunction) {
+  if (state.bufferOutput) {
+    state.bufferedMessages.push(messageFunction);
+  } else {
+    messageFunction();
+  }
 }
 
 function startProcess(message) {
@@ -91,6 +113,19 @@ 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 = {
   writeInformation,
   writeVerboseInformation,
@@ -99,4 +134,6 @@ export const ui = {
   writeExitWithoutInstallingMaliciousPackages,
   emptyLine,
   startProcess,
+  startBufferingLogs,
+  writeBufferedLogsAndStopBuffering,
 };

packages/safe-chain/src/main.js

@@ -25,8 +25,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;
     }

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

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