diff --git a/CHANGELOG.md b/CHANGELOG.md index e171e217116..9e3af2394c9 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/src/emulator/downloadableEmulators.spec.ts b/src/emulator/downloadableEmulators.spec.ts index f4dc93448b0..eefd7c74f73 100644 --- a/src/emulator/downloadableEmulators.spec.ts +++ b/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"); + }); +}); diff --git a/src/emulator/downloadableEmulators.ts b/src/emulator/downloadableEmulators.ts index 5fc9ae5db41..c50f1aebb93 100755 --- a/src/emulator/downloadableEmulators.ts +++ b/src/emulator/downloadableEmulators.ts @@ -433,6 +433,16 @@ export function requiresJava(emulator: Emulators): boolean { 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,15 +502,17 @@ async function _runBinary( `${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, @@ -508,7 +520,7 @@ async function _runBinary( ); } - 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); } diff --git a/src/emulator/loggingEmulator.spec.ts b/src/emulator/loggingEmulator.spec.ts index 94c0dbb8054..ec9ce95e8aa 100644 --- a/src/emulator/loggingEmulator.spec.ts +++ b/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((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((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((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((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; + } + }); }); diff --git a/src/emulator/loggingEmulator.ts b/src/emulator/loggingEmulator.ts index 45f90e1bca1..658290729c0 100644 --- a/src/emulator/loggingEmulator.ts +++ b/src/emulator/loggingEmulator.ts @@ -40,7 +40,9 @@ export class LoggingEmulator implements EmulatorInstance { constructor(private args: LoggingEmulatorArgs) {} start(): Promise { - 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(); history: LogEntry[] = []; - constructor(options = {}) { + constructor(options: TransportStream.TransportStreamOptions = {}) { super(options); this.setMaxListeners(30); } diff --git a/src/logger.spec.ts b/src/logger.spec.ts index ec5bfb1124e..22d46b11200 100644 --- a/src/logger.spec.ts +++ b/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); + } + }); + }); }); diff --git a/src/logger.ts b/src/logger.ts index ff8dbb5fcc9..8a4d6d2245d 100644 --- a/src/logger.ts +++ b/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",