fix: stream downloadable emulator logs to Emulator UI

CHANGELOG.md

@@ -4,3 +4,4 @@
 - Fixed a race condition in `SourceTokenScraper` that could cause concurrent function deployments to hang when refreshing an expired source token (#6989).
 - Fixed an issue where a Function Kit and a functions codebase sharing the same source directory failed `firebase.json` validation. (#11253)
 - Fixed an issue where Cloud Functions creation did not retry on HTTP 403 service account propagation errors. (#11251)
+- Fixed an issue where logs from downloadable emulators (such as Cloud Firestore and Realtime Database) were not streamed to the Emulator Suite UI.

src/emulator/downloadableEmulators.spec.ts

@@ -102,3 +102,32 @@ describe("downloadDetails", () => {
     expect(downloadableEmulators.emulatorVersionOverride(Emulators.PUBSUB)).to.equal(fakeVersion);
   });
 });
+
+describe("parseLogLevel", () => {
+  it("should parse SEVERE and ERROR logs as ERROR", () => {
+    expect(downloadableEmulators.parseLogLevel("SEVERE: Unhandled exception")).to.equal("ERROR");
+    expect(downloadableEmulators.parseLogLevel("ERROR: Rules evaluation failed")).to.equal("ERROR");
+    expect(downloadableEmulators.parseLogLevel("[error] something failed")).to.equal("ERROR");
+  });
+
+  it("should parse WARNING and WARN logs as WARN", () => {
+    expect(downloadableEmulators.parseLogLevel("WARNING: Permission denied")).to.equal("WARN");
+    expect(downloadableEmulators.parseLogLevel("WARN: Deprecated syntax")).to.equal("WARN");
+    expect(downloadableEmulators.parseLogLevel("[warning] check rules")).to.equal("WARN");
+  });
+
+  it("should parse INFO logs as INFO", () => {
+    expect(downloadableEmulators.parseLogLevel("INFO: Cloud Firestore Emulator running")).to.equal(
+      "INFO",
+    );
+    expect(downloadableEmulators.parseLogLevel("[info] Listening on port 8080")).to.equal("INFO");
+  });
+
+  it("should default to DEBUG when no higher severity keyword matches", () => {
+    expect(downloadableEmulators.parseLogLevel("FINE: Detailed trace message")).to.equal("DEBUG");
+    expect(downloadableEmulators.parseLogLevel("API endpoint: http://localhost:8080")).to.equal(
+      "DEBUG",
+    );
+    expect(downloadableEmulators.parseLogLevel("Some informational text")).to.equal("DEBUG");
+  });
+});

src/emulator/downloadableEmulators.ts

@@ -1,4 +1,4 @@
 const lsofi = require("lsofi");
 import {
   Emulators,
   DownloadableEmulators,
@@ -116,7 +116,7 @@
         version: emulatorUiDetails.version,
         downloadPath: path.join(CACHE_DIR, emulatorUiDetails.downloadPathRelativeToCacheDir),
         unzipDir: path.join(CACHE_DIR, `ui-v${emulatorUiDetails.version}`),
         binaryPath: path.join(CACHE_DIR, emulatorUiDetails.binaryPathRelativeToCacheDir!),
         opts: {
           ...emulatorUiDetails,
           cacheDir: CACHE_DIR,
@@ -136,7 +136,7 @@
         unzipDir: path.join(CACHE_DIR, `pubsub-emulator-${EMULATOR_UPDATE_DETAILS.pubsub.version}`),
         binaryPath: path.join(
           CACHE_DIR,
           EMULATOR_UPDATE_DETAILS.pubsub.binaryPathRelativeToCacheDir!,
         ),
         opts: {
           ...EMULATOR_UPDATE_DETAILS.pubsub,
@@ -165,7 +165,7 @@
 
   if (overrideVersion && overrideVersion !== details.version) {
     const oldVersion = details.version;
     const replaceVersion = (s: string) => s.split(oldVersion).join(overrideVersion);
 
     details.version = overrideVersion;
     details.downloadPath = replaceVersion(details.downloadPath);
@@ -273,7 +273,7 @@
     shell: false,
   },
   pubsub: {
     binary: `${getExecPath(Emulators.PUBSUB)!}`,
     args: [],
     optionalArgs: ["port", "host"],
     joinArgs: true,
@@ -309,7 +309,7 @@
 }
 
 /**
  * @param name
  */
 export function getLogFileName(name: string): string {
   return `${name}-debug.log`;
@@ -322,7 +322,7 @@
  */
 export function _getCommand(
   emulator: DownloadableEmulators,
   args: { [s: string]: any },
 ): DownloadableEmulatorCommand {
   const baseCmd = Commands[emulator];
   const defaultPort = Constants.getDefaultPort(emulator);
@@ -335,7 +335,7 @@
   if (
     baseCmd.binary === "java" &&
     utils.isRunningInWSL() &&
     (!args.host || !args.host.includes(":"))
   ) {
     // HACK(https://github.com/firebase/firebase-tools-ui/issues/332): Force
     // Java to use IPv4 sockets in WSL (unless IPv6 address explicitly used).
@@ -433,6 +433,16 @@
   return false;
 }
 
+/**
+ * Parses the severity level from a downloadable emulator output line.
+ */
+export function parseLogLevel(text: string): "INFO" | "WARN" | "ERROR" | "DEBUG" {
+  if (/\b(SEVERE|ERROR)\b/i.test(text)) return "ERROR";
+  if (/\b(WARNING|WARN)\b/i.test(text)) return "WARN";
+  if (/\bINFO\b/i.test(text)) return "INFO";
+  return "DEBUG";
+}
+
 async function _runBinary(
   emulator: DownloadableEmulatorDetails,
   command: DownloadableEmulatorCommand,
@@ -492,23 +502,25 @@
       `${description} logging to ${clc.bold(getLogFileName(emulator.name))}`,
     );
 
-    emulator.instance.stdout?.on("data", (data) => {
-      logger.log("DEBUG", data.toString());
+    emulator.instance.stdout?.on("data", (data: Buffer) => {
+      const text = data.toString();
+      logger.log(parseLogLevel(text), text);
       emulator.stdout.write(data);
     });
-    emulator.instance.stderr?.on("data", (data) => {
-      logger.log("DEBUG", data.toString());
+    emulator.instance.stderr?.on("data", (data: Buffer) => {
+      const text = data.toString();
+      logger.log(parseLogLevel(text), text);
       emulator.stdout.write(data);
 
-      if (data.toString().includes("java.lang.UnsupportedClassVersionError")) {
+      if (text.includes("java.lang.UnsupportedClassVersionError")) {
         logger.logLabeled(
           "WARN",
           emulator.name,
           "Unsupported java version, make sure java --version reports 1.8 or higher.",
         );
       }
 
-      if (data.toString().includes("address already in use")) {
+      if (text.includes("address already in use")) {
         const message = `${description} has exited because its configured port ${command.port} is already in use. Are you running another copy of the emulator suite?`;
         logger.logLabeled("ERROR", emulator.name, message);
       }

src/emulator/loggingEmulator.spec.ts

@@ -50,4 +50,107 @@ describe("LoggingEmulator", () => {
     const receivedMessage = await messagePromise;
     expect(receivedMessage.message).to.contain("Hello world from unit test!");
   });
+
+  it("should discard debug messages when DEBUG env is not set", async () => {
+    const originalDebug = process.env.DEBUG;
+    const originalLevel = logger.level;
+    delete process.env.DEBUG;
+    logger.level = "info";
+
+    try {
+      emulator = new LoggingEmulator({ port, host: "127.0.0.1" });
+      await emulator.start();
+
+      const ws = new WebSocket(`ws://127.0.0.1:${port}`);
+      client = ws;
+
+      const received: LogEntry[] = [];
+      const infoPromise = new Promise<void>((resolve, reject) => {
+        const timeout = setTimeout(() => {
+          reject(new Error("Timeout waiting for info message"));
+        }, 5000);
+
+        ws.on("message", (data) => {
+          try {
+            const entry = JSON.parse(data.toString()) as LogEntry;
+            received.push(entry);
+            if (entry.message.includes("Info message after debug")) {
+              clearTimeout(timeout);
+              resolve();
+            }
+          } catch (e) {
+            clearTimeout(timeout);
+            reject(e);
+          }
+        });
+      });
+
+      await new Promise<void>((resolve, reject) => {
+        ws.on("open", () => resolve());
+        ws.on("error", (err) => reject(err));
+      });
+
+      logger.debug("Should be ignored");
+      logger.info("Info message after debug");
+
+      await infoPromise;
+      expect(received.some((m) => m.message.includes("Should be ignored"))).to.be.false;
+      expect(received.some((m) => m.message.includes("Info message after debug"))).to.be.true;
+    } finally {
+      if (originalDebug !== undefined) {
+        process.env.DEBUG = originalDebug;
+      } else {
+        delete process.env.DEBUG;
+      }
+      logger.level = originalLevel;
+    }
+  });
+
+  it("should broadcast debug messages when DEBUG env is set", async () => {
+    const originalDebug = process.env.DEBUG;
+    const originalLevel = logger.level;
+    process.env.DEBUG = "true";
+    logger.level = "debug";
+
+    try {
+      emulator = new LoggingEmulator({ port, host: "127.0.0.1" });
+      await emulator.start();
+
+      const ws = new WebSocket(`ws://127.0.0.1:${port}`);
+      client = ws;
+
+      const messagePromise = new Promise<LogEntry>((resolve, reject) => {
+        const timeout = setTimeout(() => {
+          reject(new Error("Timeout waiting for debug message"));
+        }, 5000);
+
+        ws.on("message", (data) => {
+          clearTimeout(timeout);
+          try {
+            resolve(JSON.parse(data.toString()) as LogEntry);
+          } catch (e) {
+            reject(e);
+          }
+        });
+      });
+
+      await new Promise<void>((resolve, reject) => {
+        ws.on("open", () => resolve());
+        ws.on("error", (err) => reject(err));
+      });
+
+      logger.debug("Debug message from unit test!");
+
+      const receivedMessage = await messagePromise;
+      expect(receivedMessage.level).to.equal("debug");
+      expect(receivedMessage.message).to.contain("Debug message from unit test!");
+    } finally {
+      if (originalDebug !== undefined) {
+        process.env.DEBUG = originalDebug;
+      } else {
+        delete process.env.DEBUG;
+      }
+      logger.level = originalLevel;
+    }
+  });
 });

src/emulator/loggingEmulator.ts

@@ -40,7 +40,9 @@ export class LoggingEmulator implements EmulatorInstance {
   constructor(private args: LoggingEmulatorArgs) {}
 
   start(): Promise<void> {
-    this.transport = new WebSocketTransport();
+    this.transport = new WebSocketTransport({
+      level: process.env.DEBUG ? "debug" : "info",
+    });
     this.transport.start(this.getInfo());
     logger.add(this.transport);
     return Promise.resolve();
@@ -78,7 +80,7 @@ class WebSocketTransport extends TransportStream {
   connections = new Set<WebSocket>();
   history: LogEntry[] = [];
 
-  constructor(options = {}) {
+  constructor(options: TransportStream.TransportStreamOptions = {}) {
     super(options);
     this.setMaxListeners(30);
   }

src/logger.spec.ts

@@ -6,7 +6,13 @@ import * as path from "path";
 
 import * as Transport from "winston-transport";
 
-import { logger, findAvailableLogFile, resolveLogTarget, useFileLogger } from "./logger";
+import {
+  logger,
+  findAvailableLogFile,
+  resolveLogTarget,
+  useFileLogger,
+  useConsoleLoggers,
+} from "./logger";
 
 interface FileTransport extends Transport {
   dirname?: string;
@@ -27,10 +33,13 @@ function getLoggerTransports(logObj: unknown): FileTransport[] {
 
 describe("logger", () => {
   const originalEnv = process.env.FIREBASE_DEBUG_PATH;
+  const originalDebug = process.env.DEBUG;
+  let originalLevel: string;
   let testTmpDir: string;
 
   beforeEach(() => {
     delete process.env.FIREBASE_DEBUG_PATH;
+    originalLevel = logger.level;
     testTmpDir = fs.mkdtempSync(path.join(os.tmpdir(), "firebase-debug-test-"));
   });
 
@@ -40,6 +49,12 @@ describe("logger", () => {
     } else {
       delete process.env.FIREBASE_DEBUG_PATH;
     }
+    if (originalDebug !== undefined) {
+      process.env.DEBUG = originalDebug;
+    } else {
+      delete process.env.DEBUG;
+    }
+    logger.level = originalLevel;
     sinon.restore();
     if (fs.existsSync(testTmpDir)) {
       fs.rmSync(testTmpDir, { recursive: true, force: true, maxRetries: 5, retryDelay: 50 });
@@ -311,4 +326,24 @@ describe("logger", () => {
       }
     });
   });
+
+  describe("useConsoleLoggers", () => {
+    it("should set root logger level to debug when DEBUG env var is set", () => {
+      process.env.DEBUG = "true";
+      const beforeTransports = [...getLoggerTransports(logger)];
+
+      useConsoleLoggers();
+
+      expect(logger.level).to.equal("debug");
+
+      const afterTransports = getLoggerTransports(logger);
+      const addedTransports = afterTransports.filter((t) => !beforeTransports.includes(t));
+      expect(addedTransports).to.have.lengthOf(1);
+      expect(addedTransports[0].level).to.equal("debug");
+
+      for (const t of addedTransports) {
+        logger.remove(t);
+      }
+    });
+  });
 });

src/logger.ts

@@ -67,6 +67,7 @@ export interface Logger {
   remove(transport: Transport): Logger;
 
   silent: boolean;
+  level: string;
 }
 
 function expandErrors(logger: winston.Logger): winston.Logger {
@@ -297,6 +298,7 @@ export function useFileLogger(logFile?: string): string {
  */
 export function useConsoleLoggers(): void {
   if (process.env.DEBUG) {
+    logger.level = "debug";
     logger.add(
       new winston.transports.Console({
         level: "debug",