diff --git a/src/chains/ethereum/ethereum/src/blockchain.ts b/src/chains/ethereum/ethereum/src/blockchain.ts index 191fd2c0e3..c4b8dc326f 100644 --- a/src/chains/ethereum/ethereum/src/blockchain.ts +++ b/src/chains/ethereum/ethereum/src/blockchain.ts @@ -37,7 +37,8 @@ import { BUFFER_32_ZERO, BUFFER_256_ZERO, KNOWN_CHAINIDS, - keccak + keccak, + Logger } from "@ganache/utils"; import AccountManager from "./data-managers/account-manager"; import BlockManager from "./data-managers/block-manager"; @@ -105,10 +106,6 @@ type BlockchainTypedEvents = { stop: undefined; }; -interface Logger { - log(message?: any, ...optionalParams: any[]): void; -} - export type BlockchainOptions = { db?: string | object; db_path?: string; diff --git a/src/chains/ethereum/ethereum/src/provider.ts b/src/chains/ethereum/ethereum/src/provider.ts index 0d56db56f6..af2e79051b 100644 --- a/src/chains/ethereum/ethereum/src/provider.ts +++ b/src/chains/ethereum/ethereum/src/provider.ts @@ -35,7 +35,7 @@ import { MessageEvent, VmConsoleLogEvent } from "./provider-events"; - +import { closeSync } from "fs"; declare type RequestMethods = KnownKeys; function parseCoinbase( @@ -432,6 +432,12 @@ export class EthereumProvider this.#executor.stop(); await this.#blockchain.stop(); + // only need to do this if it's an `AsyncronousLogger` + if ("getCompletionHandle" in this.#options.logging.logger) { + await this.#options.logging.logger.getCompletionHandle(); + closeSync(this.#options.logging.file); + } + this.#executor.end(); this.emit("disconnect"); }; diff --git a/src/chains/ethereum/ethereum/tests/api/eth/instamine.test.ts b/src/chains/ethereum/ethereum/tests/api/eth/instamine.test.ts index bc3bf3a710..2edad65bb4 100644 --- a/src/chains/ethereum/ethereum/tests/api/eth/instamine.test.ts +++ b/src/chains/ethereum/ethereum/tests/api/eth/instamine.test.ts @@ -1,6 +1,6 @@ import getProvider from "../../helpers/getProvider"; import assert from "assert"; -import { Logger } from "@ganache/ethereum-options/typings/src/logging-options"; +import { Logger } from "@ganache/utils"; describe("api", () => { describe("eth", () => { diff --git a/src/chains/ethereum/ethereum/tests/provider.test.ts b/src/chains/ethereum/ethereum/tests/provider.test.ts index 536b462294..60af7d307e 100644 --- a/src/chains/ethereum/ethereum/tests/provider.test.ts +++ b/src/chains/ethereum/ethereum/tests/provider.test.ts @@ -8,6 +8,8 @@ import EthereumApi from "../src/api"; import getProvider from "./helpers/getProvider"; import compile from "./helpers/compile"; import Web3 from "web3"; +import { promises, closeSync } from "fs"; +const { stat, unlink } = promises; describe("provider", () => { describe("options", () => { @@ -644,6 +646,34 @@ describe("provider", () => { }); }); + it("closes the logging fileDescriptor", async () => { + const filePath = "./closes-logging-descriptor.log"; + const provider = await getProvider({ logging: { file: filePath } }); + + try { + const descriptor = (await provider).getOptions().logging.file; + assert.strictEqual( + typeof descriptor, + "number", + `File descriptor has unexepected value ${typeof descriptor}` + ); + + assert( + (await stat(filePath)).isFile(), + `log file: ${filePath} was not created` + ); + + await provider.disconnect(); + + assert.throws( + () => closeSync(descriptor), + "File descriptor is still valid after disconnect() called" + ); + } finally { + await unlink(filePath); + } + }); + // todo: Reinstate this test when https://github.com/trufflesuite/ganache/issues/3499 is fixed describe.skip("without asyncRequestProcessing", () => { // we only test this with asyncRequestProcessing: false, because it's impossible to force requests diff --git a/src/chains/ethereum/options/src/index.ts b/src/chains/ethereum/options/src/index.ts index fb90a7cf8d..6237361edc 100644 --- a/src/chains/ethereum/options/src/index.ts +++ b/src/chains/ethereum/options/src/index.ts @@ -7,14 +7,12 @@ import { ForkConfig, ForkOptions } from "./fork-options"; import { Base, Defaults, - Definitions, ExternalConfig, InternalConfig, Legacy, LegacyOptions, OptionName, OptionRawType, - Options, OptionsConfig } from "@ganache/options"; import { UnionToIntersection } from "./helper-types"; @@ -45,11 +43,9 @@ export type EthereumLegacyProviderOptions = Partial< MakeLegacyOptions >; -export type EthereumProviderOptions = Partial< - { - [K in keyof EthereumConfig]: ExternalConfig; - } ->; +export type EthereumProviderOptions = Partial<{ + [K in keyof EthereumConfig]: ExternalConfig; +}>; export type EthereumInternalOptions = { [K in keyof EthereumConfig]: InternalConfig; diff --git a/src/chains/ethereum/options/src/logging-options.ts b/src/chains/ethereum/options/src/logging-options.ts index e6700d207a..3a092502a2 100644 --- a/src/chains/ethereum/options/src/logging-options.ts +++ b/src/chains/ethereum/options/src/logging-options.ts @@ -1,9 +1,7 @@ import { normalize } from "./helpers"; import { Definitions } from "@ganache/options"; - -export type Logger = { - log(message?: any, ...optionalParams: any[]): void; -}; +import { openSync, PathLike } from "fs"; +import { Logger, createLogger } from "@ganache/utils"; export type LoggingConfig = { options: { @@ -74,6 +72,15 @@ export type LoggingConfig = { type: boolean; hasDefault: true; }; + + /** + * If you set this option, Ganache will write logs to a file located at the + * specified path. + */ + readonly file: { + type: number; + rawType: PathLike; + }; }; }; @@ -92,17 +99,6 @@ export const LoggingOptions: Definitions = { cliAliases: ["q", "quiet"], cliType: "boolean" }, - logger: { - normalize, - cliDescription: - "An object, like `console`, that implements a `log` function.", - disableInCLI: true, - // disable the default logger if `quiet` is `true` - default: config => ({ - log: config.quiet ? () => {} : console.log - }), - legacyName: "logger" - }, verbose: { normalize, cliDescription: "Set to `true` to log detailed RPC requests.", @@ -110,5 +106,41 @@ export const LoggingOptions: Definitions = { legacyName: "verbose", cliAliases: ["v", "verbose"], cliType: "boolean" + }, + file: { + normalize: (raw: PathLike): number => { + let descriptor: number; + + try { + descriptor = openSync(raw, "a"); + } catch (err) { + throw new Error( + `Failed to open log file ${raw}. Please check if the file path is valid and if the process has write permissions to the directory.` + ); + } + return descriptor; + }, + cliDescription: + "If set, Ganache will write logs to a file located at the specified path.", + cliType: "string" + }, + logger: { + normalize: (logger: Logger, config: Readonly<{ file: number }>) => { + return createLogger({ + file: config.file, + baseLogger: logger + }); + }, + cliDescription: + "An object, like `console`, that implements a `log` function.", + disableInCLI: true, + default: config => { + const baseLogger = config.quiet ? { log: () => {} } : console; + return createLogger({ + file: config.file, + baseLogger + }); + }, + legacyName: "logger" } }; diff --git a/src/chains/ethereum/options/src/miner-options.ts b/src/chains/ethereum/options/src/miner-options.ts index f6246929f3..559f5bb779 100644 --- a/src/chains/ethereum/options/src/miner-options.ts +++ b/src/chains/ethereum/options/src/miner-options.ts @@ -220,7 +220,7 @@ const toNumberOrString = (str: string) => { return parseInt(str); } }; - +const normalizeQuantity = value => Quantity.from(value); export const MinerOptions: Definitions = { blockTime: { normalize: rawInput => { @@ -246,7 +246,7 @@ export const MinerOptions: Definitions = { cliType: "string" }, defaultGasPrice: { - normalize: Quantity.from, + normalize: normalizeQuantity, cliDescription: "Sets the default gas price in WEI for transactions if not otherwise specified.", default: () => Quantity.from(2_000_000_000), @@ -256,7 +256,7 @@ export const MinerOptions: Definitions = { cliCoerce: toBigIntOrString }, blockGasLimit: { - normalize: Quantity.from, + normalize: normalizeQuantity, cliDescription: "Sets the block gas limit in WEI.", default: () => Quantity.from(30_000_000), legacyName: "gasLimit", @@ -274,7 +274,7 @@ export const MinerOptions: Definitions = { cliCoerce: estimateOrToBigIntOrString }, difficulty: { - normalize: Quantity.from, + normalize: normalizeQuantity, cliDescription: "Sets the block difficulty. Value is always 0 after the merge hardfork.", default: () => Quantity.One, @@ -282,7 +282,7 @@ export const MinerOptions: Definitions = { cliCoerce: toBigIntOrString }, callGasLimit: { - normalize: Quantity.from, + normalize: normalizeQuantity, cliDescription: "Sets the transaction gas limit in WEI for `eth_call` and `eth_estimateGas` calls.", default: () => Quantity.from(50_000_000), diff --git a/src/chains/ethereum/options/tests/index.test.ts b/src/chains/ethereum/options/tests/index.test.ts index fe5a2057ac..111d46abe4 100644 --- a/src/chains/ethereum/options/tests/index.test.ts +++ b/src/chains/ethereum/options/tests/index.test.ts @@ -1,32 +1,7 @@ import assert from "assert"; import { EthereumDefaults, EthereumOptionsConfig } from "../src"; -import sinon from "sinon"; describe("EthereumOptionsConfig", () => { - describe("options", () => { - let spy: any; - beforeEach(() => { - spy = sinon.spy(console, "log"); - }); - afterEach(() => { - spy.restore(); - }); - it("logs via console.log by default", () => { - const message = "message"; - const options = EthereumOptionsConfig.normalize({}); - options.logging.logger.log(message); - assert.strictEqual(spy.withArgs(message).callCount, 1); - }); - - it("disables the logger when the quiet flag is used", () => { - const message = "message"; - const options = EthereumOptionsConfig.normalize({ - logging: { quiet: true } - }); - options.logging.logger.log(message); - assert.strictEqual(spy.withArgs(message).callCount, 0); - }); - }); describe(".normalize", () => { it("returns an options object with all default namespaces", () => { const options = EthereumOptionsConfig.normalize({}); diff --git a/src/chains/ethereum/options/tests/logging-options.test.ts b/src/chains/ethereum/options/tests/logging-options.test.ts new file mode 100644 index 0000000000..978343d74e --- /dev/null +++ b/src/chains/ethereum/options/tests/logging-options.test.ts @@ -0,0 +1,203 @@ +import assert from "assert"; +import { EthereumOptionsConfig } from "../src"; +import sinon from "sinon"; +import { resolve } from "path"; +import { promises } from "fs"; +const { unlink, readFile, open } = promises; +import { closeSync } from "fs"; +import { URL } from "url"; + +describe("EthereumOptionsConfig", () => { + describe("logging", () => { + const validFilePath = resolve("./tests/test-file.log"); + + describe("options", () => { + let spy: any; + beforeEach(() => { + spy = sinon.spy(console, "log"); + }); + + afterEach(() => { + spy.restore(); + }); + + describe("logger", () => { + it("uses console.log by default", () => { + const message = "message"; + const options = EthereumOptionsConfig.normalize({}); + options.logging.logger.log(message); + assert.strictEqual(spy.withArgs(message).callCount, 1); + }); + + it("disables the logger when the quiet flag is used", () => { + const message = "message"; + const options = EthereumOptionsConfig.normalize({ + logging: { quiet: true } + }); + options.logging.logger.log(message); + assert.strictEqual(spy.withArgs(message).callCount, 0); + }); + + it("calls the provided logger when quiet flag is used", () => { + const logLines: string[][] = []; + const options = EthereumOptionsConfig.normalize({ + logging: { + quiet: true, + logger: { + log: (message: any, ...params: any[]) => + logLines.push([message, ...params]) + } + } + }); + + options.logging.logger.log("message", "param1", "param2"); + + assert.deepStrictEqual(logLines, [["message", "param1", "param2"]]); + }); + }); + + describe("file", () => { + it("resolves a file path to descriptor", async () => { + const options = EthereumOptionsConfig.normalize({ + logging: { file: validFilePath } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("resolves a file path as Buffer to descriptor", async () => { + const options = EthereumOptionsConfig.normalize({ + logging: { file: Buffer.from(validFilePath, "utf8") } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("resolves a file URL as Buffer to descriptor", async () => { + const options = EthereumOptionsConfig.normalize({ + logging: { file: new URL(`file://${validFilePath}`) } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("fails if the process doesn't have write access to the file path provided", async () => { + const file = resolve("./eperm-file.log"); + try { + const handle = await open(file, "w"); + // set no permissions on the file + await handle.chmod(0); + await handle.close(); + + const error = { + message: `Failed to open log file ${file}. Please check if the file path is valid and if the process has write permissions to the directory.` + }; + + assert.throws( + () => + EthereumOptionsConfig.normalize({ + logging: { file } + }), + error + ); + } finally { + await unlink(file); + } + }); + + it("should append to the specified file", async () => { + const message = "message"; + const handle = await open(validFilePath, "w"); + try { + await handle.write("existing content"); + await handle.close(); + + const options = EthereumOptionsConfig.normalize({ + logging: { file: validFilePath } + }); + options.logging.logger.log(message); + closeSync(options.logging.file); + + const readHandle = await open(validFilePath, "r"); + const content = await readHandle.readFile({ encoding: "utf8" }); + await readHandle.close(); + assert( + content.startsWith("existing content"), + "Existing content was overwritten by the logger" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("uses the provided logger, and file when both `logger` and `file` are provided", async () => { + const calls: any[] = []; + const logger = { + log: (message: any, ...params: any[]) => { + calls.push([message, ...params]); + } + }; + + try { + const options = EthereumOptionsConfig.normalize({ + logging: { + logger, + file: validFilePath + } + }); + + options.logging.logger.log("message", "param1", "param2"); + if ("getCompletionHandle" in options.logging.logger) { + //wait for the logs to be written to disk + await options.logging.logger.getCompletionHandle(); + } else { + throw new Error("Expected options.logging.logger to be AsyncronousLogger"); + } + closeSync(options.logging.file); + + assert.deepStrictEqual(calls, [["message", "param1", "param2"]]); + + const fromFile = await readFile(validFilePath, "utf8"); + assert(fromFile !== "", "Nothing written to the log file"); + + const timestampPart = fromFile.substring(0, 24); + + const timestampRegex = + /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}Z$/; + assert( + timestampPart.match(timestampRegex), + `Unexpected timestamp from file ${timestampPart}` + ); + + const messagePart = fromFile.substring(25); + + assert.strictEqual(messagePart, "message param1 param2\n"); + } finally { + await unlink(validFilePath); + } + }); + }); + }); + }); +}); diff --git a/src/chains/filecoin/options/package-lock.json b/src/chains/filecoin/options/package-lock.json index c111c2873d..07dc0c5294 100644 --- a/src/chains/filecoin/options/package-lock.json +++ b/src/chains/filecoin/options/package-lock.json @@ -41,6 +41,41 @@ "@jridgewell/sourcemap-codec": "^1.4.10" } }, + "@sinonjs/commons": { + "version": "1.8.6", + "resolved": "https://registry.npmjs.org/@sinonjs/commons/-/commons-1.8.6.tgz", + "integrity": "sha512-Ky+XkAkqPZSm3NLBeUng77EBQl3cmeJhITaGHdYH8kjVB+aun3S4XBRti2zt17mtt0mIUDiNxYeoJm6drVvBJQ==", + "dev": true, + "requires": { + "type-detect": "4.0.8" + } + }, + "@sinonjs/fake-timers": { + "version": "8.1.0", + "resolved": "https://registry.npmjs.org/@sinonjs/fake-timers/-/fake-timers-8.1.0.tgz", + "integrity": "sha512-OAPJUAtgeINhh/TAlUID4QTs53Njm7xzddaVlEs/SXwgtiD1tW22zAB/W1wdqfrpmikgaWQ9Fw6Ws+hsiRm5Vg==", + "dev": true, + "requires": { + "@sinonjs/commons": "^1.7.0" + } + }, + "@sinonjs/samsam": { + "version": "6.1.3", + "resolved": "https://registry.npmjs.org/@sinonjs/samsam/-/samsam-6.1.3.tgz", + "integrity": "sha512-nhOb2dWPeb1sd3IQXL/dVPnKHDOAFfvichtBf4xV00/rU1QbPCQqKMbvIheIjqwVjh7qIgf2AHTHi391yMOMpQ==", + "dev": true, + "requires": { + "@sinonjs/commons": "^1.6.0", + "lodash.get": "^4.4.2", + "type-detect": "^4.0.8" + } + }, + "@sinonjs/text-encoding": { + "version": "0.7.2", + "resolved": "https://registry.npmjs.org/@sinonjs/text-encoding/-/text-encoding-0.7.2.tgz", + "integrity": "sha512-sXXKG+uL9IrKqViTtao2Ws6dy0znu9sOaP1di/jKGW1M6VssO8vlpXCQcpZ+jisQ1tTFAC5Jo/EOzFbggBagFQ==", + "dev": true + }, "@tsconfig/node10": { "version": "1.0.9", "resolved": "https://registry.npmjs.org/@tsconfig/node10/-/node10-1.0.9.tgz", @@ -115,6 +150,21 @@ "integrity": "sha512-giB9gzDeiCeloIXDgzFBCgjj1k4WxcDrZtGl6h1IqmUPlxF+Nx8Ve+96QCyDZ/HseB/uvDsKbpib9hU5cU53pw==", "dev": true }, + "@types/sinon": { + "version": "10.0.13", + "resolved": "https://registry.npmjs.org/@types/sinon/-/sinon-10.0.13.tgz", + "integrity": "sha512-UVjDqJblVNQYvVNUsj0PuYYw0ELRmgt1Nt5Vk0pT5f16ROGfcKJY8o1HVuMOJOpD727RrGB9EGvoaTQE5tgxZQ==", + "dev": true, + "requires": { + "@types/sinonjs__fake-timers": "*" + } + }, + "@types/sinonjs__fake-timers": { + "version": "8.1.2", + "resolved": "https://registry.npmjs.org/@types/sinonjs__fake-timers/-/sinonjs__fake-timers-8.1.2.tgz", + "integrity": "sha512-9GcLXF0/v3t80caGs5p2rRfkB+a8VBGLJZVih6CNFkx8IZ994wiKKLSRs9nuFwk1HevWs/1mnUmkApGrSGsShA==", + "dev": true + }, "@types/terser-webpack-plugin": { "version": "5.0.2", "resolved": "https://registry.npmjs.org/@types/terser-webpack-plugin/-/terser-webpack-plugin-5.0.2.tgz", @@ -969,6 +1019,12 @@ "integrity": "sha512-knxG2q4UC3u8stRGyAVJCOdxFmv5DZiRcdlIaAQXAbSfJya+OhopNotLQrstBhququ4ZpuKbDc/8S6mgXgPFPw==", "dev": true }, + "isarray": { + "version": "0.0.1", + "resolved": "https://registry.npmjs.org/isarray/-/isarray-0.0.1.tgz", + "integrity": "sha512-D2S+3GLxWH+uhrNEcoh/fnmYeP8E8/zHl644d/jdA0g2uyXvy3sb0qxotE+ne0LtccHknQzWwZEzhak7oJ0COQ==", + "dev": true + }, "isexe": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/isexe/-/isexe-2.0.0.tgz", @@ -1022,6 +1078,12 @@ "minimist": "^1.2.5" } }, + "just-extend": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/just-extend/-/just-extend-4.2.1.tgz", + "integrity": "sha512-g3UB796vUFIY90VIv/WX3L2c8CS2MdWUww3CNrYmqza1Fg0DURc2K/O4YrnklBdQarSJ/y8JnJYDGc+1iumQjg==", + "dev": true + }, "keccak": { "version": "3.0.2", "resolved": "https://registry.npmjs.org/keccak/-/keccak-3.0.2.tgz", @@ -1064,6 +1126,12 @@ "p-locate": "^5.0.0" } }, + "lodash.get": { + "version": "4.4.2", + "resolved": "https://registry.npmjs.org/lodash.get/-/lodash.get-4.4.2.tgz", + "integrity": "sha512-z+Uw/vLuy6gQe8cfaFWD7p0wVv8fJl3mbzXh33RS+0oW2wvUqiRXiQ69gLWSLpgB5/6sU+r6BlQR0MBILadqTQ==", + "dev": true + }, "log-symbols": { "version": "4.1.0", "resolved": "https://registry.npmjs.org/log-symbols/-/log-symbols-4.1.0.tgz", @@ -1199,6 +1267,39 @@ "integrity": "sha512-Yd3UES5mWCSqR+qNT93S3UoYUkqAZ9lLg8a7g9rimsWmYGK8cVToA4/sF3RrshdyV3sAGMXVUmpMYOw+dLpOuw==", "dev": true }, + "nise": { + "version": "5.1.4", + "resolved": "https://registry.npmjs.org/nise/-/nise-5.1.4.tgz", + "integrity": "sha512-8+Ib8rRJ4L0o3kfmyVCL7gzrohyDe0cMFTBa2d364yIrEGMEoetznKJx899YxjybU6bL9SQkYPSBBs1gyYs8Xg==", + "dev": true, + "requires": { + "@sinonjs/commons": "^2.0.0", + "@sinonjs/fake-timers": "^10.0.2", + "@sinonjs/text-encoding": "^0.7.1", + "just-extend": "^4.0.2", + "path-to-regexp": "^1.7.0" + }, + "dependencies": { + "@sinonjs/commons": { + "version": "2.0.0", + "resolved": "https://registry.npmjs.org/@sinonjs/commons/-/commons-2.0.0.tgz", + "integrity": "sha512-uLa0j859mMrg2slwQYdO/AkrOfmH+X6LTVmNTS9CqexuE2IvVORIkSpJLqePAbEnKJ77aMmCwr1NUZ57120Xcg==", + "dev": true, + "requires": { + "type-detect": "4.0.8" + } + }, + "@sinonjs/fake-timers": { + "version": "10.0.2", + "resolved": "https://registry.npmjs.org/@sinonjs/fake-timers/-/fake-timers-10.0.2.tgz", + "integrity": "sha512-SwUDyjWnah1AaNl7kxsa7cfLhlTYoiyhDAIgyh+El30YvXs/o7OLXpYH88Zdhyx9JExKrmHDJ+10bwIcY80Jmw==", + "dev": true, + "requires": { + "@sinonjs/commons": "^2.0.0" + } + } + } + }, "node-addon-api": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/node-addon-api/-/node-addon-api-2.0.2.tgz", @@ -1306,6 +1407,15 @@ "integrity": "sha512-LDJzPVEEEPR+y48z93A0Ed0yXb8pAByGWo/k5YYdYgpY2/2EsOsksJrq7lOHxryrVOn1ejG6oAp8ahvOIQD8sw==", "dev": true }, + "path-to-regexp": { + "version": "1.8.0", + "resolved": "https://registry.npmjs.org/path-to-regexp/-/path-to-regexp-1.8.0.tgz", + "integrity": "sha512-n43JRhlUKUAlibEJhPeir1ncUID16QnEjNpwzNdO3Lm4ywrBpBZ5oLD0I6br9evr1Y9JTqwRtAh7JLoOzAQdVA==", + "dev": true, + "requires": { + "isarray": "0.0.1" + } + }, "picocolors": { "version": "1.0.0", "resolved": "https://registry.npmjs.org/picocolors/-/picocolors-1.0.0.tgz", @@ -1510,6 +1620,31 @@ "integrity": "sha512-sDl4qMFpijcGw22U5w63KmD3cZJfBuFlVNbVMKje2keoKML7X2UzWbc4XrmEbDwg0NXJc3yv4/ox7b+JWb57kQ==", "dev": true }, + "sinon": { + "version": "12.0.1", + "resolved": "https://registry.npmjs.org/sinon/-/sinon-12.0.1.tgz", + "integrity": "sha512-iGu29Xhym33ydkAT+aNQFBINakjq69kKO6ByPvTsm3yyIACfyQttRTP03aBP/I8GfhFmLzrnKwNNkr0ORb1udg==", + "dev": true, + "requires": { + "@sinonjs/commons": "^1.8.3", + "@sinonjs/fake-timers": "^8.1.0", + "@sinonjs/samsam": "^6.0.2", + "diff": "^5.0.0", + "nise": "^5.1.0", + "supports-color": "^7.2.0" + }, + "dependencies": { + "supports-color": { + "version": "7.2.0", + "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-7.2.0.tgz", + "integrity": "sha512-qpCAvRl9stuOHveKsn7HncJRvv501qIacKzQlO/+Lwxc9+0q2wLyv4Dfvt80/DPn2pqOBsJdDiogXGR9+OvwRw==", + "dev": true, + "requires": { + "has-flag": "^4.0.0" + } + } + } + }, "source-map": { "version": "0.7.3", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.7.3.tgz", @@ -1700,6 +1835,12 @@ } } }, + "type-detect": { + "version": "4.0.8", + "resolved": "https://registry.npmjs.org/type-detect/-/type-detect-4.0.8.tgz", + "integrity": "sha512-0fr/mIH1dlO+x7TlcMy+bIDqKPsw/70tVyeHW787goQjhmqaZe10uwLujubK9q9Lg6Fiho1KUKDYz0Z7k7g5/g==", + "dev": true + }, "typescript": { "version": "4.7.4", "resolved": "https://registry.npmjs.org/typescript/-/typescript-4.7.4.tgz", diff --git a/src/chains/filecoin/options/package.json b/src/chains/filecoin/options/package.json index 7dbe0abf66..4421cd3c0e 100644 --- a/src/chains/filecoin/options/package.json +++ b/src/chains/filecoin/options/package.json @@ -53,11 +53,13 @@ "@ganache/options": "0.7.1", "@types/mocha": "9.0.0", "@types/seedrandom": "3.0.1", + "@types/sinon": "10.0.13", "@types/terser-webpack-plugin": "5.0.2", "cross-env": "7.0.3", "mocha": "9.1.3", "node-loader": "1.0.2", "seedrandom": "3.0.5", + "sinon": "12.0.1", "terser-webpack-plugin": "5.2.5", "ts-loader": "9.3.1", "ts-node": "10.9.1", @@ -66,6 +68,7 @@ "webpack-cli": "4.9.1" }, "dependencies": { - "keccak": "3.0.2" + "keccak": "3.0.2", + "@ganache/utils": "0.7.1" } } diff --git a/src/chains/filecoin/options/src/logging-options.ts b/src/chains/filecoin/options/src/logging-options.ts index e85ac3445c..321863f4a0 100644 --- a/src/chains/filecoin/options/src/logging-options.ts +++ b/src/chains/filecoin/options/src/logging-options.ts @@ -1,5 +1,6 @@ -import { normalize } from "./helpers"; import { Definitions } from "@ganache/options"; +import { openSync, PathLike } from "fs"; +import { Logger, createLogger } from "@ganache/utils"; export type LoggingConfig = { options: { @@ -18,22 +19,54 @@ export type LoggingConfig = { * ``` */ readonly logger: { - type: { - log(message?: any, ...optionalParams: any[]): void; - }; + type: Logger; hasDefault: true; }; + + /** + * If you set this option, Ganache will write logs to a file located at the + * specified path. + */ + readonly file: { + type: number; + rawType: PathLike; + }; }; }; -const logger = { log: console.log }; - export const LoggingOptions: Definitions = { + file: { + normalize: (raw: PathLike): number => { + let descriptor: number; + try { + descriptor = openSync(raw, "a"); + } catch (err) { + throw new Error( + `Failed to open log file ${raw}. Please check if the file path is valid and if the process has write permissions to the directory.` + ); + } + return descriptor; + }, + + cliDescription: + "If set, Ganache will write logs to a file located at the specified path.", + cliType: "string" + }, logger: { - normalize, + normalize: (logger: Logger, config) => { + return createLogger({ + file: (config as any).file, + baseLogger: logger + }); + }, cliDescription: "An object, like `console`, that implements a `log` function.", disableInCLI: true, - default: () => logger + default: config => { + return createLogger({ + file: config.file, + baseLogger: console + }); + } } }; diff --git a/src/chains/filecoin/options/tests/logging-options.test.ts b/src/chains/filecoin/options/tests/logging-options.test.ts new file mode 100644 index 0000000000..0b650c86a4 --- /dev/null +++ b/src/chains/filecoin/options/tests/logging-options.test.ts @@ -0,0 +1,177 @@ +import assert from "assert"; +import { FilecoinOptionsConfig } from "../src"; +import sinon from "sinon"; +import { resolve } from "path"; +import { promises } from "fs"; +const { unlink, open, readFile } = promises; +import { closeSync } from "fs"; + +import { URL } from "url"; +describe("FilecoinOptionsConfig", () => { + describe("logging", () => { + const validFilePath = resolve("./tests/test-file.log"); + + describe("options", () => { + let spy: any; + beforeEach(() => { + spy = sinon.spy(console, "log"); + }); + + afterEach(() => { + spy.restore(); + }); + + describe("logger", () => { + it("uses console.log by default", () => { + const message = "message"; + const options = FilecoinOptionsConfig.normalize({}); + options.logging.logger.log(message); + assert.strictEqual(spy.withArgs(message).callCount, 1); + }); + }); + + describe("file", () => { + it("resolves a file path to descriptor", async () => { + const options = FilecoinOptionsConfig.normalize({ + logging: { file: validFilePath } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("resolves a file path as Buffer to descriptor", async () => { + const options = FilecoinOptionsConfig.normalize({ + logging: { file: Buffer.from(validFilePath, "utf8") } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("resolves a file URL as Buffer to descriptor", async () => { + const options = FilecoinOptionsConfig.normalize({ + logging: { file: new URL(`file://${validFilePath}`) } + }); + try { + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("fails if the process doesn't have write access to the file path provided", async () => { + const file = resolve("./eperm-file.log"); + try { + const handle = await open(file, "w"); + // set no permissions on the file + await handle.chmod(0); + await handle.close(); + + const error = { + message: `Failed to open log file ${file}. Please check if the file path is valid and if the process has write permissions to the directory.` + }; + + assert.throws( + () => + FilecoinOptionsConfig.normalize({ + logging: { file } + }), + error + ); + } finally { + await unlink(file); + } + }); + + it("should append to the specified file", async () => { + const message = "message"; + const handle = await open(validFilePath, "w"); + try { + await handle.write("existing content"); + handle.close(); + + const options = FilecoinOptionsConfig.normalize({ + logging: { file: validFilePath } + }); + options.logging.logger.log(message); + closeSync(options.logging.file); + + const readHandle = await open(validFilePath, "r"); + const content = await readHandle.readFile({ encoding: "utf8" }); + await readHandle.close(); + assert( + content.startsWith("existing content"), + "Existing content was overwritten by the logger" + ); + } finally { + await unlink(validFilePath); + } + }); + + it("uses the provided logger, and file when both `logger` and `file` are provided", async () => { + const calls: any[] = []; + const logger = { + log: (message: any, ...params: any[]) => { + calls.push([message, ...params]); + } + }; + + try { + const options = FilecoinOptionsConfig.normalize({ + logging: { + logger, + file: validFilePath + } + }); + + options.logging.logger.log("message", "param1", "param2"); + if ("getCompletionHandle" in options.logging.logger) { + //wait for the logs to be written to disk + await options.logging.logger.getCompletionHandle(); + } else { + throw new Error("Expected options.logging.logger to be AsyncronousLogger"); + } + closeSync(options.logging.file); + + assert.deepStrictEqual(calls, [["message", "param1", "param2"]]); + + const fromFile = await readFile(validFilePath, "utf8"); + assert(fromFile !== "", "Nothing written to the log file"); + + const timestampPart = fromFile.substring(0, 24); + + const timestampRegex = + /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}Z$/; + assert( + timestampPart.match(timestampRegex), + `Unexpected timestamp from file ${timestampPart}` + ); + + const messagePart = fromFile.substring(25); + + assert.strictEqual(messagePart, "message param1 param2\n"); + } finally { + await unlink(validFilePath); + } + }); + }); + }); + }); +}); diff --git a/src/chains/filecoin/options/tsconfig.json b/src/chains/filecoin/options/tsconfig.json index 5dfe28e945..4c788f00e3 100644 --- a/src/chains/filecoin/options/tsconfig.json +++ b/src/chains/filecoin/options/tsconfig.json @@ -15,6 +15,10 @@ { "name": "@ganache/options", "path": "../../../packages/options" + }, + { + "name": "@ganache/utils", + "path": "../../../packages/utils" } ] } \ No newline at end of file diff --git a/src/packages/cli/package-lock.json b/src/packages/cli/package-lock.json index c04613a00f..518de0bc81 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 f3789e8b4e..278a83cf65 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 ed27ce8356..78bb7f0015 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,39 @@ export default function ( stopArgs.action = "stop"; } ) + .command( + chalk( + `logs [--follow] [--since ] [--until ]` + ), + highlight( + "Fetch logs for the instance specified by \n\n" + + " can be a linux timestamp e.g., `759927600000`,\n" + + "an ISO formatted timestamp `1994-01-30T11:00:00.000Z`\n" + + "or relative e.g., `60 seconds`." + ), + logsArgs => { + logsArgs.positional("name", { type: "string" }); + logsArgs + .options("follow", { + type: "boolean", + alias: ["f"], + description: "Continue streaming the instance's logs" + }) + .options("since ", { + type: "string", + alias: ["s"], + description: highlight("Show logs since ") + }) + .options("until ", { + type: "string", + alias: ["u"], + description: highlight("Show logs up until ") + }); + }, + logsArgs => { + logsArgs.action = "logs"; + } + ) .version(false); } ) @@ -307,6 +341,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 +356,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 1864b4d374..76cf387665 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) => { @@ -89,6 +91,7 @@ if (argv.action === "start") { case ServerStatus.open: console.log("Shutting down…"); await server.close(); + console.log("Server has been shut down"); break; } @@ -171,6 +174,38 @@ 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.error( + `No logs found for ${porscheColor( + instanceName + )}. The log file may have been deleted.\n\nYou may need to restart the instance.` + ); + } + }); + 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 c4860bc32c..b9f94a2197 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; @@ -28,6 +29,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. */ @@ -42,12 +47,18 @@ export function notifyDetachedInstanceReady(port: number) { * @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; @@ -77,7 +88,7 @@ export async function stopDetachedInstance( } catch (err) { return false; } finally { - await removeDetachedInstanceFile(instanceName); + await removeDetachedInstanceFiles(instanceName); } return true; } @@ -98,10 +109,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"], @@ -158,7 +199,7 @@ export async function startDetachedInstance( const instance: DetachedInstance = { startTime, pid, - name: createInstanceName(), + name: instanceName, host, port, flavor, @@ -166,33 +207,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; } @@ -221,62 +237,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); @@ -294,7 +318,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..6ff064c8bf --- /dev/null +++ b/src/packages/cli/src/logs-stream.ts @@ -0,0 +1,115 @@ +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); + } + 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 + }) + .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(); + }); + }) + .on("error", err => followStream.emit("error", err)); + } + createStream(); + + return followStream; +} 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..8ddbb89df3 --- /dev/null +++ b/src/packages/cli/tests/logs-stream.test.ts @@ -0,0 +1,283 @@ +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"; + +function readFromStream(stream: Readable): Promise { + return new Promise((resolve, reject) => { + const chunks: Buffer[] = []; + stream + .on("data", chunk => chunks.push(chunk)) + .on("end", () => resolve(Buffer.concat(chunks).toString("utf8"))) + .on("error", reject); + }); +} + +const fixturePath = "./tests/logs.fixture.log"; +const fixtureContents = readFileSync(fixturePath, "utf8"); + +describe("logs-stream", () => { + describe("createFollowReadStream()", () => { + 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); + + try { + const logsReadAfterEOF = await new Promise( + (resolve, reject) => { + const logLines: Buffer[] = []; + + logStream + // start reading log lines immediately, otherwise the file contents are buffered + .on("data", () => {}) + // we wait until eof, so that we can ignore everything that's already in the file + .once("eof", () => { + logStream + .on("data", data => logLines.push(data)) + .once("eof", () => { + const logs = Buffer.concat(logLines).toString("utf8"); + resolve(logs); + }); + appendFile(fixturePath, newLogLine); + }) + .on("error", reject); + } + ); + + assert.deepStrictEqual(logsReadAfterEOF, newLogLine); + } finally { + logStream.destroy(); + // rewrite the contents back to the fixture file, removing the additional data that we appended + 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 = logLines.slice(logLinesToSkip).join(""); + + const filteredStream = filterLogsStream({ input, since }); + + const result = await readFromStream(filteredStream); + + assert.strictEqual( + result, + 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 = logLines.slice(0, logLinesToReturn).join(""); + + const filteredStream = filterLogsStream({ input, until }); + const result = await readFromStream(filteredStream); + + assert.strictEqual( + result, + 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("should read the specified file", async () => { + const logsStream = getLogsStream(fixturePath, {}); + const result = await readFromStream(logsStream); + logsStream.destroy(); + + assert.strictEqual(result, fixtureContents); + }); + + it("should filter the specified date range", async () => { + const fixtureLines = fixtureContents.split("\n"); + const skipFromFront = 2; + const skipFromBack = 2; + + const matchingLines = fixtureLines.slice( + skipFromFront, + fixtureLines.length - skipFromBack - 1 // -1 because 0-based index + ); + + const since = Date.parse(matchingLines[0].slice(0, 24)); + const until = Date.parse( + matchingLines[matchingLines.length - 1].slice(0, 24) + ); + + const logsStream = getLogsStream(fixturePath, { + since, + until + }); + + const result = await readFromStream(logsStream); + logsStream.destroy(); + + assert.strictEqual( + result, + matchingLines.join("\n") + "\n", + `expected only long lines since ${new Date( + since + ).toISOString()} and until ${new Date(until).toISOString()}` + ); + }); + + it("should follow the specified file", async () => { + const newLogLine = `${new Date().toISOString()} new log line\n`; + + const logStream = getLogsStream(fixturePath, { + follow: true + }); + + try { + const logsReadAfterEOF = await new Promise( + (resolve, reject) => { + const logLines: Buffer[] = []; + + logStream + // start reading log lines immediately, otherwise the file contents are buffered + .on("data", () => {}) + // we wait until eof, so that we can ignore everything that's already in the file + .once("eof", () => { + logStream + .on("data", data => logLines.push(data)) + .once("eof", () => { + const logs = Buffer.concat(logLines).toString("utf8"); + resolve(logs); + }); + appendFile(fixturePath, newLogLine); + }) + .on("error", reject); + } + ); + + assert.deepStrictEqual(logsReadAfterEOF, newLogLine); + } finally { + logStream.destroy(); + // rewrite the contents back to the fixture file, removing the additional data that we appended + writeFile(fixturePath, fixtureContents); + } + }); + + it("should follow the specified file, returning the filtered results", async () => { + const fixtureLines = fixtureContents.split("\n"); + const skipFromFront = 2; + const skipFromBack = 2; + + const matchingLines = fixtureLines.slice( + skipFromFront, + fixtureLines.length - skipFromBack - 1 // -1 because 0-based index + ); + + const since = Date.parse(matchingLines[0].slice(0, 24)); + const until = Date.parse( + matchingLines[matchingLines.length - 1].slice(0, 24) + ); + + const tooEarlyLogLine = `${new Date( + since - 10 + ).toISOString()} non-matching log line\n`; + + const matchingLogLine = `${new Date( + since + ).toISOString()} matching log line\n`; + + const tooLateLogLine = `${new Date( + until + 10 + ).toISOString()} non-matching log line\n`; + + const logStream = getLogsStream(fixturePath, { + since, + until, + follow: true + }); + + try { + const logsReadAfterEOF = await new Promise( + (resolve, reject) => { + const logLines: Buffer[] = []; + + logStream + // start reading log lines immediately, otherwise the file contents are buffered + .on("data", () => {}) + // we wait until eof, so that we can ignore everything that's already in the file + .once("eof", () => { + logStream + .on("data", data => logLines.push(data)) + .once("eof", () => { + const logs = Buffer.concat(logLines).toString("utf8"); + resolve(logs); + }); + appendFile( + fixturePath, + [tooEarlyLogLine, matchingLogLine, tooLateLogLine].join("\n") + ); + }) + .on("error", reject); + } + ); + + assert.deepStrictEqual(logsReadAfterEOF, matchingLogLine); + } finally { + logStream.destroy(); + // rewrite the contents back to the fixture file, removing the additional data that we appended + writeFile(fixturePath, fixtureContents); + } + }); + }); +}); diff --git a/src/packages/cli/tests/logs.fixture.log b/src/packages/cli/tests/logs.fixture.log new file mode 100644 index 0000000000..b01e4671e7 --- /dev/null +++ b/src/packages/cli/tests/logs.fixture.log @@ -0,0 +1,13 @@ +2023-03-10T09:00:01.000Z truffle_machine: Starting new batch of truffles. +2023-03-10T09:00:02.000Z truffle_machine: Added 2 cups of cocoa powder to the mixing bowl. +2023-03-10T09:00:03.000Z truffle_machine: Added 1 cup of sugar to the mixing bowl. +2023-03-10T09:00:04.000Z truffle_machine: Added 1 cup of cream to the mixing bowl. +2023-03-10T09:00:05.000Z truffle_machine: Mixed ingredients for 15 minutes. +2023-03-10T09:15:05.000Z truffle_machine: Finished mixing ingredients. +2023-03-10T09:15:06.000Z truffle_machine: Shaped mixture into truffles and placed in fridge to cool. +2023-03-10T09:30:06.000Z ganache_machine: Starting new batch of ganache. +2023-03-10T09:30:07.000Z ganache_machine: Added 3 cups of dark chocolate chips to the melting pot. +2023-03-10T09:30:08.000Z ganache_machine: Added 1 cup of heavy cream to the melting pot. +2023-03-10T09:30:09.000Z ganache_machine: Melted ingredients and mixed for 5 minutes. +2023-03-10T09:35:09.000Z ganache_machine: Finished mixing ingredients. +2023-03-10T09:35:10.000Z ganache_machine: Poured ganache into molds and placed in fridge to cool. diff --git a/src/packages/core/tests/connector.test.ts b/src/packages/core/tests/connector.test.ts index 0969407b6a..d6ebf5eef3 100644 --- a/src/packages/core/tests/connector.test.ts +++ b/src/packages/core/tests/connector.test.ts @@ -9,29 +9,33 @@ describe("connector", () => { }); it("it logs when `options.verbose` is `true`", async () => { - const logger = { log: (_msg: string) => {} }; + const logLines: string[] = []; + const logger = { + log: (_msg: string) => { + logLines.push(_msg); + } + }; const p = Ganache.provider({ logging: { logger, verbose: true } }); - logger.log = msg => { - assert.strictEqual( - msg, - " > net_version: undefined", - "doesn't work when no params" - ); - }; await p.send("net_version"); + assert.deepStrictEqual( + logLines, + [" > net_version: undefined"], + "doesn't work when no params" + ); - return new Promise(async resolve => { - logger.log = msg => { - const expected = - " > web3_sha3: [\n" + ' > "Tim is a swell guy."\n' + " > ]"; - assert.strictEqual(msg, expected, "doesn't work with params"); - resolve(); - }; - await p.send("web3_sha3", ["Tim is a swell guy."]); - }); + // clear the logLines + logLines.splice(0, logLines.length); + + const message = `0x${Buffer.from("Tim is a swell guy.").toString("hex")}`; + await p.send("web3_sha3", [message]); + assert.deepStrictEqual( + logLines, + [` > web3_sha3: [\n > \"${message}\"\n > ]`], + "doesn't work with params" + ); }); it("it processes requests asynchronously when `asyncRequestProcessing` is default (true)", async () => { @@ -108,7 +112,7 @@ describe("connector", () => { const illegalMethodTypes = [ 123, // just cast as string to make TS let me test weird stuff... - (Buffer.from([1]) as unknown) as string, + Buffer.from([1]) as unknown as string, null, void 0, {}, diff --git a/src/packages/ganache/npm-shrinkwrap.json b/src/packages/ganache/npm-shrinkwrap.json index d1c3d8ea90..7fc6489c08 100644 --- a/src/packages/ganache/npm-shrinkwrap.json +++ b/src/packages/ganache/npm-shrinkwrap.json @@ -1,6 +1,6 @@ { "name": "ganache", - "version": "7.5.0", + "version": "7.7.6", "lockfileVersion": 1, "requires": true, "dependencies": { diff --git a/src/packages/options/src/create.ts b/src/packages/options/src/create.ts index c52b46b1bc..78582a0274 100644 --- a/src/packages/options/src/create.ts +++ b/src/packages/options/src/create.ts @@ -6,11 +6,9 @@ import { hasOwn } from "@ganache/utils"; export type NamespacedOptions = { [key: string]: Base.Config }; -export type ProviderOptions = Partial< - { - [K in keyof O]: ExternalConfig; - } ->; +export type ProviderOptions = Partial<{ + [K in keyof O]: ExternalConfig; +}>; export type InternalOptions = { [K in keyof O]: InternalConfig; @@ -53,7 +51,7 @@ function fill(defaults: any, options: any, target: any, namespace: any) { const propDefinition = def[key]; let value = namespaceOptions[key]; if (value !== undefined) { - const normalized = propDefinition.normalize(namespaceOptions[key]); + const normalized = propDefinition.normalize(value, config); if (normalized !== undefined) { checkForConflicts( key, @@ -68,7 +66,7 @@ function fill(defaults: any, options: any, target: any, namespace: any) { const legacyName = propDefinition.legacyName || key; value = options[legacyName]; if (value !== undefined) { - const normalized = propDefinition.normalize(value); + const normalized = propDefinition.normalize(value, config); if (normalized !== undefined) { checkForConflicts( key, @@ -92,7 +90,7 @@ function fill(defaults: any, options: any, target: any, namespace: any) { const legacyName = propDefinition.legacyName || key; const value = options[legacyName]; if (value !== undefined) { - const normalized = propDefinition.normalize(value); + const normalized = propDefinition.normalize(value, config); if (normalized !== undefined) { checkForConflicts( key, diff --git a/src/packages/options/src/definition.ts b/src/packages/options/src/definition.ts index 6f22099219..66b3d4d908 100644 --- a/src/packages/options/src/definition.ts +++ b/src/packages/options/src/definition.ts @@ -19,15 +19,17 @@ import { UnionToIntersection } from "./types"; type Normalize< C extends Base.Config, N extends OptionName = OptionName -> = (rawInput: OptionRawType) => OptionType; +> = ( + rawInput: OptionRawType, + config: Readonly> +) => OptionType; export type ExternalConfig = Partial< ExclusiveGroupUnionAndUnconstrainedPlus >; -export type InternalConfig< - C extends Base.Config -> = ExclusiveGroupUnionAndUnconstrainedPlus; +export type InternalConfig = + ExclusiveGroupUnionAndUnconstrainedPlus; export type Definitions = { [N in OptionName]: { diff --git a/src/packages/utils/index.ts b/src/packages/utils/index.ts index 9763262908..4e3eebe2dd 100644 --- a/src/packages/utils/index.ts +++ b/src/packages/utils/index.ts @@ -14,3 +14,4 @@ export { JsonRpcErrorCode } from "./src/things/jsonrpc"; export { default as PromiEvent } from "./src/things/promievent"; +export * from "./src/things/logger"; diff --git a/src/packages/utils/src/things/logger.ts b/src/packages/utils/src/things/logger.ts new file mode 100644 index 0000000000..052c36fdbe --- /dev/null +++ b/src/packages/utils/src/things/logger.ts @@ -0,0 +1,61 @@ +import { appendFile } from "fs"; +import { promisify, format } from "util"; +const appendFilePromise = promisify(appendFile); +export type LogFunc = (message?: any, ...optionalParams: any[]) => void; + +type SyncronousLogger = { + log: LogFunc; +}; +type AsyncronousLogger = SyncronousLogger & { + getCompletionHandle: () => Promise; +}; + +export type Logger = SyncronousLogger | AsyncronousLogger; + +export function createLogger(config: { + file: number; + baseLogger: Logger; +}): AsyncronousLogger; +export function createLogger(config: { baseLogger: Logger }): SyncronousLogger; +export function createLogger(config: { + file?: number; + baseLogger: Logger; +}): Logger { + if (config.file === undefined) { + return config.baseLogger; + } else { + if (typeof config.file !== "number") { + throw new Error( + `'config.file' was not correctly noramlized to a file descriptor. This should not happen. ${ + config.file + }: ${typeof config.file}` + ); + } + const descriptor = config.file; + + const diskLogFormatter = (message: any) => { + const linePrefix = `${new Date().toISOString()} `; + return message.toString().replace(/^/gm, linePrefix); + }; + + let writing = Promise.resolve(null); + + const log = (message: any, ...optionalParams: any[]) => { + // we are logging to a file, but we still need to writing to console + config.baseLogger.log(message, ...optionalParams); + + const formattedMessage: string = format(message, ...optionalParams); + + writing = writing.then(() => { + return appendFilePromise( + descriptor, + diskLogFormatter(formattedMessage) + "\n" + ); + }); + }; + return { + log, + getCompletionHandle: () => writing + }; + } +} diff --git a/src/packages/utils/tests/logger.test.ts b/src/packages/utils/tests/logger.test.ts new file mode 100644 index 0000000000..4c33e08778 --- /dev/null +++ b/src/packages/utils/tests/logger.test.ts @@ -0,0 +1,182 @@ +import assert from "assert"; +import { createLogger } from "../src/things/logger"; +import { openSync, promises, closeSync } from "fs"; +const { readFile, unlink } = promises; + +const getFileDescriptor = (slug: string) => { + const path = `./tests/test-${slug}.log`; + return { + path, + descriptor: openSync(path, "a") + }; +}; + +describe("createLogger()", () => { + const timestampRegex = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.\d{3}Z$/; + + const createbaseLoggerger = () => { + const calls: any[][] = []; + return { + baseLogger: { + log: (message, ...params) => { + calls.push([message, ...params]); + } + }, + calls + }; + }; + + const message = "test message"; + + describe("log()", () => { + it("should create a baseLogger() logger", () => { + const { baseLogger, calls } = createbaseLoggerger(); + const { log } = createLogger({ baseLogger }); + + log(message); + + assert.strictEqual( + calls.length, + 1, + "baseLogger() was called unexpected number of times." + ); + + const baseLoggerArgs = calls[0]; + + assert.deepStrictEqual( + baseLoggerArgs, + [message], + "baseLogger() called with unexpected arguments." + ); + }); + + it("should still call baseLogger() when a file is specified", async () => { + const { descriptor, path } = getFileDescriptor("write-to-console"); + const { baseLogger, calls } = createbaseLoggerger(); + + const { log, getCompletionHandle } = createLogger({ + file: descriptor, + baseLogger + }); + + try { + log(message); + await getCompletionHandle(); + } finally { + closeSync(descriptor); + await unlink(path); + } + + assert.strictEqual( + calls.length, + 1, + "baseLogger() was called unexpected number of times." + ); + + const args = calls[0]; + + assert.deepStrictEqual( + args, + [message], + "baseLogger() called with unexpected arguments." + ); + }); + + it("should write to the file provided", async () => { + const { descriptor, path } = getFileDescriptor("write-to-file-provided"); + const { baseLogger } = createbaseLoggerger(); + + const { log, getCompletionHandle } = createLogger({ + file: descriptor, + baseLogger + }); + + let fileContents: string; + try { + log(`${message} 0`); + log(`${message} 1`); + log(`${message} 2`); + await getCompletionHandle(); + + fileContents = await readFile(path, "utf8"); + } finally { + closeSync(descriptor); + await unlink(path); + } + + const logLines = fileContents.split("\n"); + + // 4, because there's a \n at the end of each line + assert.strictEqual(logLines.length, 4); + assert.strictEqual(logLines[3], ""); + + logLines.slice(0, 3).forEach((logLine, lineNumber) => { + const timestampPart = logLine.slice(0, 24); + const messagePart = logLine.slice(25); + const delimiter = logLine[24]; + + assert(timestampRegex.test(timestampPart), "Unexpected timestamp."); + assert.strictEqual(delimiter, " ", "Unexpected delimiter."); + assert.strictEqual( + messagePart, + `${message} ${lineNumber}`, + "Unexpected message." + ); + }); + }); + + it("should timestamp each line on multi-line log messages", async () => { + const { descriptor, path } = getFileDescriptor("timestamp-each-line"); + const { baseLogger } = createbaseLoggerger(); + + const { log, getCompletionHandle } = createLogger({ + file: descriptor, + baseLogger + }); + + const expectedLines = ["multi", "line", "message"]; + + let loggedLines: string[]; + try { + log(expectedLines.join("\n")); + await getCompletionHandle(); + + const fileContents = await readFile(path, "utf8"); + loggedLines = fileContents.split("\n"); + } finally { + closeSync(descriptor); + await unlink(path); + } + + // length == 4, because there's a \n at the end (string.split() results + // in each log line, follwed by an empty string) + assert.strictEqual(loggedLines.length, 4); + assert.strictEqual(loggedLines[3], ""); + + loggedLines.slice(0, 3).forEach((logLine, lineNumber) => { + const timestampPart = logLine.slice(0, 24); + const messagePart = logLine.slice(25); + const delimiter = logLine[24]; + + assert(timestampRegex.test(timestampPart), "Unexpected timestamp"); + assert.strictEqual(delimiter, " ", "Unexpected delimiter"); + assert.strictEqual(messagePart, expectedLines[lineNumber]); + }); + }); + + it("should throw if the file descriptor is invalid", async () => { + // unlikely that this will be a valid file descriptor + const descriptor = 1234567890; + const { baseLogger } = createbaseLoggerger(); + + const { log, getCompletionHandle } = createLogger({ + file: descriptor, + baseLogger + }); + + log("descriptor is invalid"); + + await assert.rejects(getCompletionHandle(), { code: "EBADF" }); + }); + }); +});