From 4ab79d7de1caa827430e8ee1bd0056817a69f3b5 Mon Sep 17 00:00:00 2001 From: Jeff Smale <6363749+jeffsmale90@users.noreply.github.com> Date: Wed, 22 Feb 2023 16:50:06 +1300 Subject: [PATCH] implement 'ganache instances logs ' with support for --since, --until, and --follow --- src/packages/cli/package-lock.json | 5 + src/packages/cli/package.json | 3 +- src/packages/cli/src/args.ts | 51 ++++++ src/packages/cli/src/cli.ts | 36 +++- src/packages/cli/src/detach.ts | 194 ++++++++++++--------- src/packages/cli/src/logs-stream.ts | 125 +++++++++++++ src/packages/cli/src/types.ts | 6 + src/packages/cli/tests/logs-stream.test.ts | 148 ++++++++++++++++ 8 files changed, 480 insertions(+), 88 deletions(-) create mode 100644 src/packages/cli/src/logs-stream.ts create mode 100644 src/packages/cli/tests/logs-stream.test.ts diff --git a/src/packages/cli/package-lock.json b/src/packages/cli/package-lock.json index efa4f1ba72..ddb1d2daf3 100644 --- a/src/packages/cli/package-lock.json +++ b/src/packages/cli/package-lock.json @@ -881,6 +881,11 @@ "p-limit": "^3.0.2" } }, + "parse-duration": { + "version": "1.0.2", + "resolved": "https://registry.npmjs.org/parse-duration/-/parse-duration-1.0.2.tgz", + "integrity": "sha512-Dg27N6mfok+ow1a2rj/nRjtCfaKrHUZV2SJpEn/s8GaVUSlf4GGRCRP1c13Hj+wfPKVMrFDqLMLITkYKgKxyyg==" + }, "path-exists": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/path-exists/-/path-exists-4.0.0.tgz", diff --git a/src/packages/cli/package.json b/src/packages/cli/package.json index 27fc8e81e0..c4dcff2f55 100644 --- a/src/packages/cli/package.json +++ b/src/packages/cli/package.json @@ -72,6 +72,7 @@ "@types/node": "17.0.0", "chalk": "4.1.0", "cli-table": "0.3.11", - "marked-terminal": "4.1.0" + "marked-terminal": "4.1.0", + "parse-duration": "1.0.2" } } diff --git a/src/packages/cli/src/args.ts b/src/packages/cli/src/args.ts index 5899d980c0..0054b2a580 100644 --- a/src/packages/cli/src/args.ts +++ b/src/packages/cli/src/args.ts @@ -17,6 +17,7 @@ import { EOL } from "os"; import marked from "marked"; import TerminalRenderer from "marked-terminal"; import { _DefaultServerOptions } from "@ganache/core"; +import parseDuration from "parse-duration"; marked.setOptions({ renderer: new TerminalRenderer({ @@ -272,6 +273,30 @@ export default function ( stopArgs.action = "stop"; } ) + .command( + "logs ", + "fetch logs for the instance specified by ", + logsArgs => { + logsArgs.positional("name", { type: "string" }); + logsArgs + .options("follow", { + type: "boolean", + alias: ["f"], + description: "continue streaming the instances logs" + }) + .options("since", { + type: "string", + alias: ["s"] + }) + .options("until", { + type: "string", + alias: ["u"] + }); + }, + logsArgs => { + logsArgs.action = "logs"; + } + ) .version(false); } ) @@ -307,6 +332,14 @@ export default function ( "flavor" | "action" >) }; + } else if (parsedArgs.action === "logs") { + finalArgs = { + action: "logs", + name: parsedArgs.name as string, + follow: parsedArgs.follow as boolean, + since: getTimestampFromInput(parsedArgs.since as string), + until: getTimestampFromInput(parsedArgs.until as string) + }; } else { throw new Error(`Unknown action: ${parsedArgs.action}`); } @@ -314,6 +347,24 @@ export default function ( return finalArgs; } +function getTimestampFromInput(input: string): number | null { + if (input == null) { + return null; + } + + const parsedDate = Date.parse(input); + if (!Number.isNaN(parsedDate)) { + return parsedDate; + } + + const duration = parseDuration(input, "ms"); + if (duration == null) { + throw new Error(`Invalid duration ${input}`); + } + + return Date.now() - duration; +} + /** * Expands the arguments into an object including only namespaced keys from the * `args` argument. diff --git a/src/packages/cli/src/cli.ts b/src/packages/cli/src/cli.ts index bcb9a17e74..63d929f4e9 100644 --- a/src/packages/cli/src/cli.ts +++ b/src/packages/cli/src/cli.ts @@ -13,12 +13,14 @@ import { stopDetachedInstance, startDetachedInstance, getDetachedInstances, - formatUptime + formatUptime, + getInstanceLogsPath, + getDetachedInstanceByName } from "./detach"; import { TruffleColors } from "@ganache/colors"; import Table from "cli-table"; import chalk from "chalk"; - +import { getLogsStream } from "./logs-stream"; const porscheColor = chalk.hex(TruffleColors.porsche); const logAndForceExit = (messages: any[], exitCode = 0) => { @@ -170,6 +172,36 @@ if (argv.action === "start") { console.error("Instance not found"); } }); +} else if (argv.action === "logs") { + const instanceName = argv.name; + + getDetachedInstanceByName(instanceName) + .then(_ => { + const path = getInstanceLogsPath(instanceName); + + const stream = getLogsStream(path, { + follow: argv.follow, + since: argv.since, + until: argv.until + }); + + stream.on("error", err => { + if ((err as NodeJS.ErrnoException).code === "ENOENT") { + console.log( + `No logs are available for ${instanceName}.\nTry calling some RPC methods.` + ); + } + }); + stream.pipe(process.stdout); + //todo: we need to be able to quit from this if `--follow` is provided + }) + .catch(err => { + if ((err as NodeJS.ErrnoException).code === "ENOENT") { + console.error("Instance not found"); + } else { + console.error(err); + } + }); } else if (argv.action === "start-detached") { startDetachedInstance(process.argv, argv, version) .then(instance => { diff --git a/src/packages/cli/src/detach.ts b/src/packages/cli/src/detach.ts index 02c3904dc1..0beed4eb7d 100644 --- a/src/packages/cli/src/detach.ts +++ b/src/packages/cli/src/detach.ts @@ -4,9 +4,10 @@ import envPaths from "env-paths"; import psList, { ProcessDescriptor } from "@trufflesuite/ps-list"; import { Dirent, promises as fsPromises } from "fs"; // this awkward import is required to support node 12 -const { readFile, mkdir, readdir, rmdir, writeFile, unlink } = fsPromises; +const { readFile, mkdir, readdir, rmdir, open, unlink } = fsPromises; import path from "path"; import { FlavorName } from "@ganache/flavors"; +import { FileHandle } from "fs/promises"; export type DetachedInstance = { name: string; @@ -29,6 +30,10 @@ function getInstanceFilePath(instanceName: string): string { return path.join(dataPath, `${instanceName}.json`); } +export function getInstanceLogsPath(instanceName: string): string { + return path.join(dataPath, `${instanceName}.log`); +} + /** * Notify that the detached instance has started and is ready to receive requests. */ @@ -43,12 +48,18 @@ export function notifyDetachedInstanceReady() { * @param {string} instanceName the name of the instance to be removed * @returns boolean indicating whether the instance file was cleaned up successfully */ -export async function removeDetachedInstanceFile( +export async function removeDetachedInstanceFiles( instanceName: string ): Promise { const instanceFilename = getInstanceFilePath(instanceName); + const instanceLogFilename = getInstanceLogsPath(instanceName); try { - await unlink(instanceFilename); + await Promise.all([ + unlink(instanceFilename), + unlink(instanceLogFilename).catch(err => { + if (err.code !== "ENOENT") throw err; + }) + ]); return true; } catch {} return false; @@ -78,7 +89,7 @@ export async function stopDetachedInstance( } catch (err) { return false; } finally { - await removeDetachedInstanceFile(instanceName); + await removeDetachedInstanceFiles(instanceName); } return true; } @@ -99,10 +110,40 @@ export async function startDetachedInstance( ): Promise { const [bin, module, ...args] = argv; + let instanceName = createInstanceName(); + let filehandle: FileHandle; + while (true) { + const instanceFilename = getInstanceFilePath(instanceName); + try { + filehandle = await open(instanceFilename, "wx"); + break; + } catch (err) { + switch ((err as NodeJS.ErrnoException).code) { + case "EEXIST": + // an instance already exists with this name + instanceName = createInstanceName(); + break; + case "ENOENT": + // we don't check whether the folder exists before writing, as that's + // a very uncommon case. Catching the exception and subsequently + // creating the directory is faster in the majority of cases. + await mkdir(dataPath, { recursive: true }); + break; + default: + throw err; + } + } + } + // append `--no-detach` argument to cancel out --detach and aliases (must be // the last argument). See test "is false, when proceeded with --no-detach" in // args.test.ts - const childArgs = [...args, "--no-detach"]; + const childArgs = [ + ...args, + "--no-detach", + "--logging.file", + getInstanceLogsPath(instanceName) + ]; const child = fork(module, childArgs, { stdio: ["ignore", "ignore", "pipe", "ipc"], @@ -157,7 +198,7 @@ export async function startDetachedInstance( const instance: DetachedInstance = { startTime, pid, - name: createInstanceName(), + name: instanceName, host, port, flavor, @@ -165,33 +206,8 @@ export async function startDetachedInstance( version }; - while (true) { - const instanceFilename = getInstanceFilePath(instance.name); - try { - await writeFile(instanceFilename, JSON.stringify(instance), { - // wx means "Open file for writing, but fail if the path exists". see - // https://nodejs.org/api/fs.html#file-system-flags - flag: "wx", - encoding: FILE_ENCODING - }); - break; - } catch (err) { - switch ((err as NodeJS.ErrnoException).code) { - case "EEXIST": - // an instance already exists with this name - instance.name = createInstanceName(); - break; - case "ENOENT": - // we don't check whether the folder exists before writing, as that's - // a very uncommon case. Catching the exception and subsequently - // creating the directory is faster in the majority of cases. - await mkdir(dataPath, { recursive: true }); - break; - default: - throw err; - } - } - } + await filehandle.write(JSON.stringify(instance), 0, FILE_ENCODING); + await filehandle.close(); return instance; } @@ -220,62 +236,70 @@ export async function getDetachedInstances(): Promise { } const instances: DetachedInstance[] = []; - const loadingInstancesInfos = dirEntries.map(async dirEntry => { - const filename = dirEntry.name; - const { name: instanceName, ext } = path.parse(filename); - - let failureReason: string; - - if (ext !== ".json") { - failureReason = `"${filename}" does not have a .json extension`; - } else { - let instance: DetachedInstance; - try { - // getDetachedInstanceByName() throws if the instance file is not found or - // cannot be parsed - instance = await getDetachedInstanceByName(instanceName); - } catch (err: any) { - failureReason = err.message; - } - if (instance) { - const matchingProcess = processes.find(p => p.pid === instance.pid); - if (!matchingProcess) { - failureReason = `Process with PID ${instance.pid} could not be found`; - } else if (matchingProcess.cmd !== instance.cmd) { - failureReason = `Process with PID ${instance.pid} does not match ${instanceName}`; - } else { - instances.push(instance); - } - } - } - - if (failureReason !== undefined) { - someInstancesFailed = true; - const fullPath = path.join(dataPath, filename); - let resolution: string; - if (dirEntry.isDirectory()) { - const reason = `"${filename}" is a directory`; - try { - await rmdir(fullPath, { recursive: true }); - failureReason = reason; - } catch { - resolution = `"${filename}" could not be removed`; - } + const loadingInstancesInfos = dirEntries + .map(dirEntry => { + const { name: instanceName, ext } = path.parse(dirEntry.name); + return { + instanceName, + ext, + filename: dirEntry.name, + isDirectory: dirEntry.isDirectory + }; + }) + .filter(({ ext }) => ext !== ".log") + .map(async ({ ext, instanceName, filename, isDirectory }) => { + let failureReason: string; + + if (ext !== ".json") { + failureReason = `"${filename}" does not have a .json extension`; } else { + let instance: DetachedInstance; try { - await unlink(fullPath); - } catch { - resolution = `"${filename}" could not be removed`; + // getDetachedInstanceByName() throws if the instance file is not found or + // cannot be parsed + instance = await getDetachedInstanceByName(instanceName); + } catch (err: any) { + failureReason = err.message; + } + if (instance) { + const matchingProcess = processes.find(p => p.pid === instance.pid); + if (!matchingProcess) { + failureReason = `Process with PID ${instance.pid} could not be found`; + } else if (matchingProcess.cmd !== instance.cmd) { + failureReason = `Process with PID ${instance.pid} does not match ${instanceName}`; + } else { + instances.push(instance); + } } } - console.warn( - `Failed to load instance data. ${failureReason}. ${ - resolution || `"${filename}" has been removed` - }.` - ); - } - }); + if (failureReason !== undefined) { + someInstancesFailed = true; + const fullPath = path.join(dataPath, filename); + let resolution: string; + if (isDirectory()) { + const reason = `"${filename}" is a directory`; + try { + await rmdir(fullPath, { recursive: true }); + failureReason = reason; + } catch { + resolution = `"${filename}" could not be removed`; + } + } else { + try { + await unlink(fullPath); + } catch { + resolution = `"${filename}" could not be removed`; + } + } + + console.warn( + `Failed to load instance data. ${failureReason}. ${ + resolution || `"${filename}" has been removed` + }.` + ); + } + }); await Promise.all(loadingInstancesInfos); @@ -293,7 +317,7 @@ export async function getDetachedInstances(): Promise { * the instance file is not found or cannot be parsed * @param {string} instanceName */ -async function getDetachedInstanceByName( +export async function getDetachedInstanceByName( instanceName: string ): Promise { const filepath = getInstanceFilePath(instanceName); diff --git a/src/packages/cli/src/logs-stream.ts b/src/packages/cli/src/logs-stream.ts new file mode 100644 index 0000000000..3db5f06929 --- /dev/null +++ b/src/packages/cli/src/logs-stream.ts @@ -0,0 +1,125 @@ +import { createReadStream, FSWatcher, watch } from "fs"; +import { Readable } from "stream"; +import * as readline from "readline"; + +export type LogsStreamOptions = Partial<{ + follow: boolean; + since: number; + until: number; +}>; + +export function getLogsStream( + path: string, + options: LogsStreamOptions +): Readable { + let logsStream: Readable; + if (options.follow) { + logsStream = createFollowReadStream(path); + } else { + logsStream = createReadStream(path, { encoding: "utf8" }); + } + if (options.since != null || options.until != null) { + return filterLogsStream({ + input: logsStream, + since: options.since, + until: options.until + }); + } else { + return logsStream; + } +} + +export function filterLogsStream(args: { + input: Readable; + since?: number; + until?: number; +}) { + const { input, since, until } = args; + + if (since == null && until == null) { + return input; + } else { + const outstream = new Readable({ + read: (size: number) => {} + }); + + const rl = readline.createInterface(input); + + rl.on("line", line => { + if (since != null || until != null) { + const date = Date.parse(line.substring(0, 24)); + if ( + (since == null || date >= since) && + (until == null || date <= until) + ) { + outstream.push(Buffer.from(`${line}\n`, "utf8")); + } + } else { + outstream.push(Buffer.from(`${line}\n`, "utf8")); + } + }); + + input + .on("end", () => { + outstream.emit("end"); + }) + .on("eof", () => { + outstream.emit("eof"); + }); + return outstream; + } +} + +/** + * Creates a {Readable} stream of data from the file specified by {filename}. + * Continues to stream as data is appended to the file. Note: the file must be + * written to append-only, updates to existing data will result in undefined + * behaviour. + * @param {string} filename + * @returns {Readable} a stream of the file + */ +export function createFollowReadStream(filename: string): Readable { + let currentSize = 0; + let directFileStream: Readable; + let watcher: FSWatcher; + + const followStream = new Readable({ + // noop because the data is _pushed_ into `followStream` + read: function (size: number) {} + }); + + function createStream() { + directFileStream = createReadStream(filename, { + start: currentSize, + encoding: "utf8" + }) + .on("data", data => { + currentSize += data.length; + const chunk = Buffer.isBuffer(data) ? data : Buffer.from(data, "utf8"); + + //push the chunk into `followStream`'s internal buffer + followStream.push(chunk); + }) + .on("end", () => { + directFileStream.destroy(); + followStream.emit("eof"); + watcher = watch(filename, () => { + watcher.close(); + createStream(); + }); + }); + } + createStream(); + + return followStream; +} + +function readFromBuffers(buffers: Buffer[], size?: number) { + const entireBuffer = Buffer.concat(buffers.splice(0, buffers.length)); + if (size == undefined || size <= entireBuffer.length) { + return entireBuffer; + } else { + buffers.push(entireBuffer.slice(size + 1)); + return entireBuffer.slice(0, size); + } +} diff --git a/src/packages/cli/src/types.ts b/src/packages/cli/src/types.ts index 1cb603e559..bec7ec21b6 100644 --- a/src/packages/cli/src/types.ts +++ b/src/packages/cli/src/types.ts @@ -20,6 +20,12 @@ export type StartArgs = export type GanacheArgs = | (AbstractArgs<"stop"> & { name: string }) + | (AbstractArgs<"logs"> & { + name: string; + follow?: boolean; + since?: number; + until?: number; + }) | AbstractArgs<"list"> | StartArgs; diff --git a/src/packages/cli/tests/logs-stream.test.ts b/src/packages/cli/tests/logs-stream.test.ts new file mode 100644 index 0000000000..a870271277 --- /dev/null +++ b/src/packages/cli/tests/logs-stream.test.ts @@ -0,0 +1,148 @@ +import assert from "assert"; +import { + filterLogsStream, + getLogsStream, + createFollowReadStream +} from "../src/logs-stream"; +import { Readable } from "stream"; +import { appendFile, writeFile } from "fs/promises"; +import { readFileSync } from "fs"; + +describe("logs-stream", () => { + const fixturePath = "./tests/logs.fixture.log"; + describe("createFollowReadStream()", () => { + const fixtureContents = readFileSync(fixturePath, "utf8"); + + it("should load all of the data from the file", async () => { + const logStream = createFollowReadStream(fixturePath); + + const logs = await new Promise((resolve, reject) => { + const logLines: Buffer[] = []; + + logStream + .on("data", data => logLines.push(data)) + .on("eof", () => { + logStream.destroy(); + resolve(Buffer.concat(logLines).toString("utf8")); + }) + .on("error", reject); + }); + + assert.deepStrictEqual(logs, fixtureContents); + }); + + it("should load data appended after reading to the end of file", async () => { + const newLogLine = `${new Date().toISOString()} new log line\n`; + + const logStream = createFollowReadStream(fixturePath); + + // don't `await`, because we need to write the file back to it's original state + const loadingLogs = await new Promise((resolve, reject) => { + const logLines: Buffer[] = []; + + logStream + // start reading log lines immediately, otherwise the file contents are buffered + .on("data", () => {}) + .once("eof", () => { + logStream + .on("data", data => logLines.push(data)) + .once("eof", () => { + logStream.destroy(); + const logs = Buffer.concat(logLines).toString("utf8"); + resolve(logs); + }); + appendFile(fixturePath, newLogLine); + }) + .on("error", reject); + }); + + try { + assert.deepStrictEqual(await loadingLogs, newLogLine); + } finally { + writeFile(fixturePath, fixtureContents); + } + }); + }); + + describe("filterLogsStream()", () => { + // First log stamped at epoch + const epoch = Date.parse("2020-01-01 00:00:00 UTC"); + // subsequent logs are each incremented by 1 minute + const timestampFromLineNumber = i => epoch + i * 60000; + const logLines = [...new Array(1000)].map( + (_, i) => + `${new Date(timestampFromLineNumber(i)).toISOString()} Log line ${i}\n` + ); + + it("should return the input stream when no filter parameters are provided", async () => { + const input = Readable.from(logLines); + + const filteredStream = filterLogsStream({ input }); + + assert.strictEqual( + filteredStream, + input, + "filterLogsStream() didn't output the input stream by reference" + ); + }); + + it("should only return lines stamped equal to or later than the parameter passed as `since`", async () => { + const logLinesToSkip = 100; + const since = timestampFromLineNumber(logLinesToSkip); + + const input = Readable.from(logLines); + const expected = Buffer.from( + logLines.slice(logLinesToSkip).join(""), + "utf8" + ); + + const filteredStream = filterLogsStream({ input, since }); + + const result = await new Promise((resolve, reject) => { + const chunks: Buffer[] = []; + filteredStream + .on("data", chunk => chunks.push(chunk)) + .on("end", () => resolve(Buffer.concat(chunks))) + .on("error", reject); + }); + + assert( + result.equals(expected), + `filterLogsStream() didn't correctly skip first ${logLinesToSkip} lines from the input log stream. Expected ${expected.length} bytes. Got ${result.length} bytes` + ); + }); + + it("should only return lines stamped equal or earlier than the parameter passed as `since`", async () => { + const logLinesToReturn = 4; + // because the `until` parameter is inclusive, we must decrement by 1 in order to return the correct number of lines + const until = timestampFromLineNumber(logLinesToReturn - 1); + + const input = Readable.from(logLines); + const expected = Buffer.from( + logLines.slice(0, logLinesToReturn).join(""), + "utf8" + ); + + const filteredStream = filterLogsStream({ input, until }); + + const result = await new Promise((resolve, reject) => { + const chunks: Buffer[] = []; + filteredStream + .on("data", chunk => chunks.push(chunk)) + .on("end", () => resolve(Buffer.concat(chunks))) + .on("error", reject); + }); + + assert( + result.equals(expected), + `filterLogsStream() didn't correctly return first ${logLinesToReturn} lines from the input log stream. Expected ${expected.length} bytes. Got ${result.length} bytes` + ); + }); + }); + + describe("getLogsStream()", () => { + it("must be tested", () => { + throw new Error("todo: implement getLogsStream() tests"); + }); + }); +});