Refactoring logging to better support MCP server (#8533)

* Refactoring logging to better support MCP server

* format

Author: joehan

firebase-vscode/src/logger-wrapper.ts

@@ -6,8 +6,7 @@ import { transports, format } from "winston";
 import Transport from "winston-transport";
 import { stripVTControlCharacters } from "node:util";
 import { SPLAT } from "triple-beam";
-import { logger as cliLogger } from "../../src/logger";
-import { setupLoggers, tryStringify } from "../../src/utils";
+import { logger as cliLogger, useConsoleLoggers, useFileLogger } from "../../src/logger";
 import { setInquirerLogger } from "./stubs/inquirer-stub";
 import { getRootFolders } from "./core/config";
 
@@ -40,7 +39,7 @@ for (const logLevel in pluginLogger) {
 export function logSetup() {
   // Log to console (use built in CLI functionality)
   process.env.DEBUG = "true";
-  setupLoggers();
+  useConsoleLoggers();
 
   // Log to file
   // Only log to file if firebase.debug extension setting is true.
@@ -62,18 +61,7 @@ export function logSetup() {
     filePath = path.join(rootFolders[0], ".firebase", "logs", "vsce-debug.log");
   }
   pluginLogger.info("Logging to path", filePath);
-  cliLogger.add(
-    new transports.File({
-      level: "debug",
-      filename: filePath,
-      format: format.printf((info) => {
-        const segments = [info.message, ...(info[SPLAT] || [])].map(
-          tryStringify,
-        );
-        return `[${info.level}] ${stripVTControlCharacters(segments.join(" "))}`;
-      }),
-    }),
-  );
+  useFileLogger(filePath);
   cliLogger.add(new VSCodeOutputTransport({ level: "info" }));
 }
 

src/bin/cli.ts

@@ -5,19 +5,15 @@ import { marked } from "marked";
 marked.use(markedTerminal() as any);
 
 import { CommanderStatic } from "commander";
-import { join } from "node:path";
-import { SPLAT } from "triple-beam";
-import { stripVTControlCharacters } from "node:util";
 import * as fs from "node:fs";
 
 import { configstore } from "../configstore";
 import { errorOut } from "../errorOut";
 import { handlePreviewToggles } from "../handlePreviewToggles";
-import { logger } from "../logger";
+import { logger, useFileLogger } from "../logger";
 import * as client from "..";
 import * as fsutils from "../fsutils";
 import * as utils from "../utils";
-import * as winston from "winston";
 
 import { enableExperimentsFromCliEnvVariable } from "../experiments";
 import { fetchMOTD } from "../fetchMOTD";
@@ -28,51 +24,13 @@ export function cli(pkg: any) {
   const args = process.argv.slice(2);
   let cmd: CommanderStatic;
 
-  function findAvailableLogFile(): string {
-    const candidates = ["firebase-debug.log"];
-    for (let i = 1; i < 10; i++) {
-      candidates.push(`firebase-debug.${i}.log`);
-    }
-
-    for (const c of candidates) {
-      const logFilename = join(process.cwd(), c);
-
-      try {
-        const fd = fs.openSync(logFilename, "r+");
-        fs.closeSync(fd);
-        return logFilename;
-      } catch (e: any) {
-        if (e.code === "ENOENT") {
-          // File does not exist, which is fine
-          return logFilename;
-        }
-
-        // Any other error (EPERM, etc) means we won't be able to log to
-        // this file so we skip it.
-      }
-    }
-
-    throw new Error("Unable to obtain permissions for firebase-debug.log");
-  }
-
-  const logFilename = findAvailableLogFile();
-
   if (!process.env.DEBUG && args.includes("--debug")) {
     process.env.DEBUG = "true";
   }
 
   process.env.IS_FIREBASE_CLI = "true";
 
-  logger.add(
-    new winston.transports.File({
-      level: "debug",
-      filename: logFilename,
-      format: winston.format.printf((info) => {
-        const segments = [info.message, ...(info[SPLAT] || [])].map(utils.tryStringify);
-        return `[${info.level}] ${stripVTControlCharacters(segments.join(" "))}`;
-      }),
-    }),
-  );
+  const logFilename = useFileLogger();
 
   logger.debug("-".repeat(70));
   logger.debug("Command:      ", process.argv.join(" "));

src/bin/mcp.ts

@@ -1,8 +1,6 @@
 #!/usr/bin/env node
 
-import { silenceStdout } from "../logger";
-silenceStdout();
-
+import { useFileLogger } from "../logger";
 import { FirebaseMcpServer } from "../mcp/index";
 import { parseArgs } from "util";
 import { SERVER_FEATURES, ServerFeature } from "../mcp/types";
@@ -28,6 +26,7 @@ export async function mcp(): Promise<void> {
     },
     allowPositionals: true,
   });
+  useFileLogger();
   const activeFeatures = (values.only || "")
     .split(",")
     .filter((f) => SERVER_FEATURES.includes(f as ServerFeature)) as ServerFeature[];

src/command.ts

@@ -3,7 +3,7 @@ import { CommanderStatic } from "commander";
 import { first, last, size, head, keys, values } from "lodash";
 
 import { FirebaseError } from "./error";
-import { getInheritedOption, setupLoggers, withTimeout } from "./utils";
+import { getInheritedOption, withTimeout } from "./utils";
 import { loadRC } from "./rc";
 import { Config } from "./config";
 import { configstore } from "./configstore";
@@ -13,6 +13,7 @@ import { selectAccount, setActiveAccount } from "./auth";
 import { getProject } from "./management/projects";
 import { requireAuth } from "./requireAuth";
 import { Options } from "./options";
+import { useConsoleLoggers } from "./logger";
 
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
 type ActionFunction = (...args: any[]) => any;
@@ -311,7 +312,7 @@ export class Command {
     if (getInheritedOption(options, "json")) {
       options.nonInteractive = true;
     } else {
-      setupLoggers();
+      useConsoleLoggers();
     }
 
     if (getInheritedOption(options, "config")) {

src/index.ts

@@ -2,8 +2,7 @@ import * as program from "commander";
 import * as clc from "colorette";
 import * as leven from "leven";
 
-import { logger } from "./logger";
-import { setupLoggers } from "./utils";
+import { logger, useConsoleLoggers } from "./logger";
 
 const pkg = require("../package.json");
 
@@ -76,7 +75,7 @@ const RENAMED_COMMANDS: Record<string, string> = {
 
 // Default handler, this is called when no other command action matches.
 program.action((_, args) => {
-  setupLoggers();
+  useConsoleLoggers();
 
   const cmd = args[0];
   logger.error(clc.bold(clc.red("Error:")), clc.bold(cmd), "is not a Firebase command");

src/logger.ts

@@ -1,8 +1,12 @@
 import * as winston from "winston";
 import * as Transport from "winston-transport";
+import { EventEmitter } from "events";
+import * as path from "path";
+import * as fs from "fs";
+import { SPLAT } from "triple-beam";
+import { stripVTControlCharacters } from "util";
 
 import { isVSCodeExtension } from "./vsCodeUtils";
-import { EventEmitter } from "events";
 
 /**
  * vsceLogEmitter passes CLI logs along to VSCode.
@@ -119,6 +123,42 @@ function maybeUseVSCodeLogger(logger: winston.Logger): winston.Logger {
   return logger;
 }
 
+export function findAvailableLogFile(): string {
+  const candidates = ["firebase-debug.log"];
+  for (let i = 1; i < 10; i++) {
+    candidates.push(`firebase-debug.${i}.log`);
+  }
+
+  for (const c of candidates) {
+    const logFilename = path.join(process.cwd(), c);
+    try {
+      const fd = fs.openSync(logFilename, "r+");
+      fs.closeSync(fd);
+      return logFilename;
+    } catch (e: any) {
+      if (e.code === "ENOENT") {
+        // File does not exist, which is fine
+        return logFilename;
+      }
+      // Any other error (EPERM, etc) means we won't be able to log to
+      // this file so we skip it.
+    }
+  }
+  throw new Error("Unable to obtain permissions for firebase-debug.log");
+}
+
+function tryStringify(value: any) {
+  if (typeof value === "string") {
+    return value;
+  }
+
+  try {
+    return JSON.stringify(value);
+  } catch {
+    return value;
+  }
+}
+
 const rawLogger = winston.createLogger();
 // Set a default silent logger to suppress logs during tests
 rawLogger.add(
@@ -135,12 +175,52 @@ rawLogger.exitOnError = false;
 // allow error parameters.
 // Casting looks super dodgy, but it should be safe because we know the underlying code
 // handles all parameter types we care about.
-export let logger: Logger = maybeUseVSCodeLogger(
+export const logger: Logger = maybeUseVSCodeLogger(
   annotateDebugLines(expandErrors(rawLogger)),
 ) as unknown as Logger;
 
-export function silenceStdout() {
-  logger = winston.createLogger({
-    silent: true,
-  }) as unknown as Logger;
+/**
+ * Sets up logging to the firebase-debug.log file.
+ */
+export function useFileLogger(logFile?: string): string {
+  const logFileName = logFile ?? findAvailableLogFile();
+  logger.add(
+    new winston.transports.File({
+      level: "debug",
+      filename: logFileName,
+      format: winston.format.printf((info) => {
+        const segments = [info.message, ...(info[SPLAT] || [])].map(tryStringify);
+        return `[${info.level}] ${stripVTControlCharacters(segments.join(" "))}`;
+      }),
+    }),
+  );
+  return logFileName;
+}
+
+/**
+ * Sets up logging to the command line.
+ */
+export function useConsoleLoggers(): void {
+  if (process.env.DEBUG) {
+    logger.add(
+      new winston.transports.Console({
+        level: "debug",
+        format: winston.format.printf((info) => {
+          const segments = [info.message, ...(info[SPLAT] || [])].map(tryStringify);
+          return `${stripVTControlCharacters(segments.join(" "))}`;
+        }),
+      }),
+    );
+  } else if (process.env.IS_FIREBASE_CLI) {
+    logger.add(
+      new winston.transports.Console({
+        level: "info",
+        format: winston.format.printf((info) =>
+          [info.message, ...(info[SPLAT] || [])]
+            .filter((chunk) => typeof chunk === "string")
+            .join(" "),
+        ),
+      }),
+    );
+  }
 }

src/utils.ts

@@ -12,10 +12,7 @@ import * as open from "open";
 import * as ora from "ora";
 import * as process from "process";
 import { Readable } from "stream";
-import * as winston from "winston";
-import { SPLAT } from "triple-beam";
 import { AssertionError } from "assert";
-import { stripVTControlCharacters } from "node:util";
 import { getPortPromise as getPort } from "portfinder";
 
 import { configstore } from "./configstore";
@@ -468,22 +465,6 @@ export async function promiseProps(obj: any): Promise<any> {
   return Promise.all(promises).then(() => resultObj);
 }
 
-/**
- * Attempts to call JSON.stringify on an object, if it throws return the original value
- * @param value
- */
-export function tryStringify(value: any) {
-  if (typeof value === "string") {
-    return value;
-  }
-
-  try {
-    return JSON.stringify(value);
-  } catch {
-    return value;
-  }
-}
-
 /**
  * Attempts to call JSON.parse on an object, if it throws return the original value
  * @param value
@@ -500,34 +481,6 @@ export function tryParse(value: any) {
   }
 }
 
-/**
- *
- */
-export function setupLoggers() {
-  if (process.env.DEBUG) {
-    logger.add(
-      new winston.transports.Console({
-        level: "debug",
-        format: winston.format.printf((info) => {
-          const segments = [info.message, ...(info[SPLAT] || [])].map(tryStringify);
-          return `${stripVTControlCharacters(segments.join(" "))}`;
-        }),
-      }),
-    );
-  } else if (process.env.IS_FIREBASE_CLI) {
-    logger.add(
-      new winston.transports.Console({
-        level: "info",
-        format: winston.format.printf((info) =>
-          [info.message, ...(info[SPLAT] || [])]
-            .filter((chunk) => typeof chunk === "string")
-            .join(" "),
-        ),
-      }),
-    );
-  }
-}
-
 /**
  * Runs a given function inside a spinner with a message
  */