diff --git a/scripts/link-ts-references.ts b/scripts/link-ts-references.ts index e6b1d74771..0826f37113 100644 --- a/scripts/link-ts-references.ts +++ b/scripts/link-ts-references.ts @@ -93,12 +93,12 @@ function updateConfig(config: PackageInfo) { // add package.json deps to tsconfig references: references.forEach(name => { const referenceConfig = getConfigByName(name); - if(!referenceConfig) throw new Error(`missing config ${name}`); + if (!referenceConfig) throw new Error(`missing config ${name}`); // projects that are referenced by other projects must have the `composite: true` in their tsconfig compileOptions if ( - (!referenceConfig.tsConfig.compilerOptions || - !referenceConfig.tsConfig.compilerOptions.composite) + !referenceConfig.tsConfig.compilerOptions || + !referenceConfig.tsConfig.compilerOptions.composite ) { if (!referenceConfig.tsConfig.compilerOptions) referenceConfig.tsConfig.compilerOptions = {}; @@ -137,7 +137,8 @@ function saveConfigs(configs: PackageInfo[]) { configs.forEach(({ modified, path, tsConfig }) => { if (modified) { const tsConfigFile = join(path, "tsconfig.json"); - writeFileSync(tsConfigFile, JSON5.stringify(tsConfig, null, 2)); + const body = JSON5.stringify(tsConfig, null, 2) + "\n"; + writeFileSync(tsConfigFile, body); } }); } diff --git a/src/chains/ethereum/ethereum/src/blockchain.ts b/src/chains/ethereum/ethereum/src/blockchain.ts index aec91df3b6..7ee3f5b76a 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"; @@ -106,10 +107,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..95f2591eb6 100644 --- a/src/chains/ethereum/ethereum/src/provider.ts +++ b/src/chains/ethereum/ethereum/src/provider.ts @@ -35,7 +35,6 @@ import { MessageEvent, VmConsoleLogEvent } from "./provider-events"; - declare type RequestMethods = KnownKeys; function parseCoinbase( @@ -432,6 +431,8 @@ export class EthereumProvider this.#executor.stop(); await this.#blockchain.stop(); + await this.#options.logging.logger.close(); + this.#executor.end(); this.emit("disconnect"); }; diff --git a/src/chains/ethereum/ethereum/tests/api/eth/getTransactionReceipt.test.ts b/src/chains/ethereum/ethereum/tests/api/eth/getTransactionReceipt.test.ts index 77010ce948..33200c3e3d 100644 --- a/src/chains/ethereum/ethereum/tests/api/eth/getTransactionReceipt.test.ts +++ b/src/chains/ethereum/ethereum/tests/api/eth/getTransactionReceipt.test.ts @@ -89,7 +89,8 @@ describe("api", () => { ` > \`${hash}\` has not\n` + " > yet been mined." + " See https://trfl.io/v7-instamine for additional information." - ) + ), + `Actual: ${logger.loggedStuff}` ); }); 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 ff39f7a948..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"; +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 3438e32981..056dcbf814 100644 --- a/src/chains/ethereum/ethereum/tests/provider.test.ts +++ b/src/chains/ethereum/ethereum/tests/provider.test.ts @@ -8,7 +8,11 @@ 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; import { INITCODE_TOO_LARGE } from "@ganache/ethereum-utils"; +import tmp from "tmp-promise"; +import { resolve } from "path"; describe("provider", () => { describe("options", () => { @@ -767,6 +771,39 @@ describe("provider", () => { }); }); + it("closes the logging fileDescriptor", async () => { + await tmp.withDir( + async ({ path }) => { + const filePath = resolve(path, "closes-logging-descriptor.log"); + const provider = await getProvider({ logging: { file: filePath } }); + + const descriptor = provider.getOptions().logging.file; + assert.strictEqual( + typeof descriptor, + "number", + `File descriptor has unexpected type` + ); + + 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" + ); + }, + { + // `unsafeCleanup` instructs tmp-promise to recursively remove the + // created temporary directory, even when it's not empty. + unsafeCleanup: true + } + ); + }); + // 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/package-lock.json b/src/chains/ethereum/options/package-lock.json index d440fe2bc3..00127d9544 100644 --- a/src/chains/ethereum/options/package-lock.json +++ b/src/chains/ethereum/options/package-lock.json @@ -816,6 +816,15 @@ "integrity": "sha1-jGStX9MNqxyXbiNE/+f3kqam30I=", "dev": true }, + "rimraf": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.2.tgz", + "integrity": "sha512-JZkJMZkAGFFPP2YqXZXPbMlMBgsxzE8ILs4lMIX/2o0L9UBw9O/Y3o6wFw/i9YLapcUJWwqbi3kdxIPdC62TIA==", + "dev": true, + "requires": { + "glob": "^7.1.3" + } + }, "ripemd160": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/ripemd160/-/ripemd160-2.0.2.tgz", @@ -936,6 +945,24 @@ "has-flag": "^4.0.0" } }, + "tmp": { + "version": "0.2.1", + "resolved": "https://registry.npmjs.org/tmp/-/tmp-0.2.1.tgz", + "integrity": "sha512-76SUhtfqR2Ijn+xllcI5P1oyannHNHByD80W1q447gU3mp9G9PSpGdWmjUOHRDPiHYacIk66W7ubDTuPF3BEtQ==", + "dev": true, + "requires": { + "rimraf": "^3.0.0" + } + }, + "tmp-promise": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/tmp-promise/-/tmp-promise-3.0.2.tgz", + "integrity": "sha512-OyCLAKU1HzBjL6Ev3gxUeraJNlbNingmi8IrHHEsYH8LTmEuhvYfqvhn2F/je+mjf4N58UmZ96OMEy1JanSCpA==", + "dev": true, + "requires": { + "tmp": "^0.2.0" + } + }, "to-regex-range": { "version": "5.0.1", "resolved": "https://registry.npmjs.org/to-regex-range/-/to-regex-range-5.0.1.tgz", diff --git a/src/chains/ethereum/options/package.json b/src/chains/ethereum/options/package.json index be4221257f..bceeac04cd 100644 --- a/src/chains/ethereum/options/package.json +++ b/src/chains/ethereum/options/package.json @@ -61,6 +61,7 @@ "cross-env": "7.0.3", "mocha": "9.1.3", "sinon": "12.0.1", + "tmp-promise": "3.0.2", "ts-node": "10.9.1", "typescript": "4.7.4" } 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..2ac6f33df2 100644 --- a/src/chains/ethereum/options/src/logging-options.ts +++ b/src/chains/ethereum/options/src/logging-options.ts @@ -1,9 +1,8 @@ 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, InternalLogger, createLogger } from "@ganache/utils"; +import { EOL } from "os"; export type LoggingConfig = { options: { @@ -38,7 +37,8 @@ export type LoggingConfig = { * ``` */ readonly logger: { - type: Logger; + rawType: Logger; + type: InternalLogger; hasDefault: true; legacy: { /** @@ -65,8 +65,8 @@ export type LoggingConfig = { }; /** - * Set to `true` to disable logging. This option overrides - * logging.logger and option.verbose. + * Set to `true` to disable writing logs to stdout (or logging.logger if specified). + * This option does not impact writing logs to a file (with logging.file). * * @defaultValue false */ @@ -74,6 +74,19 @@ export type LoggingConfig = { type: boolean; hasDefault: true; }; + + /** + * The file to append logs to. + * + * Can be a filename, or an instance of URL. + * note: the URL scheme must be `file`, e.g., `file://path/to/file.log`. + * + * By default no log file is created. + */ + readonly file: { + type: number; + rawType: PathLike; + }; }; }; @@ -87,22 +100,11 @@ export const LoggingOptions: Definitions = { }, quiet: { normalize, - cliDescription: "Set to `true` to disable logging.", + cliDescription: "Set to `true` to disable writing logs to `logger.log` (`stdout` by default).", default: () => false, 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 +112,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) { + const details = (err as Error).message; + 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.${EOL}${details}` + ); + } + return descriptor; + }, + cliDescription: "The file to append logs to.", + 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..2ec7d1a50f 100644 --- a/src/chains/ethereum/options/src/miner-options.ts +++ b/src/chains/ethereum/options/src/miner-options.ts @@ -221,6 +221,13 @@ const toNumberOrString = (str: string) => { } }; +// The `normalize` property expects a function with a signature of +// `normalize(value, config)`, but `Quantity.from(value, nullable)` doesn't +// match, so we wrap the `from` method in a function that matches the signature. +// We only instantiate the wrapper function once to avoid unnecessary function +// allocations. +const normalizeQuantity = value => Quantity.from(value); + export const MinerOptions: Definitions = { blockTime: { normalize: rawInput => { @@ -246,7 +253,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 +263,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 +281,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 +289,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..718b25f503 --- /dev/null +++ b/src/chains/ethereum/options/tests/logging-options.test.ts @@ -0,0 +1,238 @@ +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"; +import { EOL } from "os"; +import tmp from "tmp-promise"; + +describe("EthereumOptionsConfig", () => { + describe("logging", () => { + describe("options", async () => { + function assertLogLine(logLine: string, message: string) { + const timestampPart = logLine.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 = logLine.substring(25); + + assert.strictEqual(messagePart, message, "Message does not match"); + } + + tmp.setGracefulCleanup(); + // we use tmp.dir() rather than tmp.file() here, because we don't want the file to exist + const tempFileDir = (await tmp.dir()).path; + const logfilePath = resolve(tempFileDir, "temp-file.log"); + + let spy: any; + + beforeEach(() => { + spy = sinon.spy(console, "log"); + }); + + afterEach(async () => { + spy.restore(); + + await unlink(logfilePath).catch(() => {}); + }); + + describe("logger", () => { + it("uses a reassigned log function", async () => { + const logger = { + log: (message: any, ...optionalParams: any[]) => {} + }; + + const options = EthereumOptionsConfig.normalize({ + logging: { logger } + }); + + let called = false; + + // reassign log function + logger.log = (message: any, ...optionalParams: any[]) => { + called = true; + assert.strictEqual(message, "Test message"); + assert.deepStrictEqual(optionalParams, ["param1", "param2"]); + }; + + options.logging.logger.log("Test message", "param1", "param2"); + assert(called); + }); + + it("uses a reassigned log function, when a file is specified", async () => { + const logger = { + log: (message: any, ...optionalParams: any[]) => {} + }; + + const options = EthereumOptionsConfig.normalize({ + logging: { logger, file: logfilePath } + }); + + let called = false; + try { + // reassign log function + logger.log = (message: any, ...optionalParams: any[]) => { + called = true; + assert.strictEqual(message, "Test message"); + assert.deepStrictEqual(optionalParams, ["param1", "param2"]); + }; + + options.logging.logger.log("Test message", "param1", "param2"); + assert(called); + } finally { + await options.logging.logger.close(); + } + }); + + 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: logfilePath } + }); + assert.strictEqual(typeof options.logging.file, "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("resolves a file path as Buffer to descriptor", async () => { + const options = EthereumOptionsConfig.normalize({ + logging: { file: Buffer.from(logfilePath, "utf8") } + }); + assert.strictEqual(typeof options.logging.file, "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("resolves a file URL to descriptor", async () => { + const options = EthereumOptionsConfig.normalize({ + logging: { file: new URL(`file://${logfilePath}`) } + }); + assert.strictEqual(typeof options.logging.file, "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("fails if the process doesn't have write access to the file path provided", async () => { + await tmp.withFile(async ({ path }) => { + const handle = await open(path, "w"); + // set no permissions on the file + await handle.chmod(0); + await handle.close(); + + const errorMessage = `Failed to open log file ${path}. Please check if the file path is valid and if the process has write permissions to the directory.${EOL}`; // the specific error that follows this is OS dependent + assert.throws( + () => + EthereumOptionsConfig.normalize({ + logging: { file: path } + }), + (error: Error) => error.message.startsWith(errorMessage) + ); + }); + }); + + it("should append to the specified file", async () => { + const message = "message"; + const handle = await open(logfilePath, "w"); + await handle.write(`existing content${EOL}`); + await handle.close(); + + const options = EthereumOptionsConfig.normalize({ + logging: { file: logfilePath } + }); + try { + options.logging.logger.log(message); + + const readHandle = await open(logfilePath, "r"); + const content = await readHandle.readFile({ encoding: "utf8" }); + await readHandle.close(); + + const lines = content.split(EOL); + + assert.strictEqual(lines.length, 3); // 2 lines + empty line at the end + assert.strictEqual(lines[0], "existing content"); + + assertLogLine(lines[1], message); + } finally { + await options.logging.logger.close(); + } + }); + + 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]); + } + }; + + const options = EthereumOptionsConfig.normalize({ + logging: { + logger, + file: logfilePath + } + }); + + options.logging.logger.log("message", "param1", "param2"); + await options.logging.logger.close(); + assert.deepStrictEqual(calls, [["message", "param1", "param2"]]); + + const fromFile = await readFile(logfilePath, "utf8"); + assert(fromFile !== "", "Nothing written to the log file"); + + const lines = fromFile.split(EOL); + assert.strictEqual(lines.length, 2); // 1 line + empty line at the end + assertLogLine(lines[0], "message param1 param2"); + assert.strictEqual(lines[1], ""); + }); + }); + }); + }); +}); diff --git a/src/chains/filecoin/options/package-lock.json b/src/chains/filecoin/options/package-lock.json index f6429be4d5..4a96b8a44a 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,50 @@ "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.3.0", + "resolved": "https://registry.npmjs.org/@sinonjs/fake-timers/-/fake-timers-10.3.0.tgz", + "integrity": "sha512-V4BG07kuYSUkTCSBHG8G8TNhM+F19jXFWnQtzj+we8DrkpSBCee9Z3Ms8yiGer/dlmhe35/Xdgyo3/0rQKg7YA==", + "dev": true, + "requires": { + "@sinonjs/commons": "^3.0.0" + }, + "dependencies": { + "@sinonjs/commons": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/@sinonjs/commons/-/commons-3.0.0.tgz", + "integrity": "sha512-jXBtWAF4vmdNmZgD5FoKsVLv3rPgDnLgPbU84LIJ3otV44vJlDRokVng5v8NFJdCf/da9legHcKaRuZs4L7faA==", + "dev": true, + "requires": { + "type-detect": "4.0.8" + } + } + } + } + } + }, "node-addon-api": { "version": "2.0.2", "resolved": "https://registry.npmjs.org/node-addon-api/-/node-addon-api-2.0.2.tgz", @@ -1306,6 +1418,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", @@ -1440,6 +1561,15 @@ "integrity": "sha512-qYg9KP24dD5qka9J47d0aVky0N+b4fTU89LN9iDnjB5waksiC49rvMB0PrUJQGoTmH50XPiqOvAjDfaijGxYZw==", "dev": true }, + "rimraf": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.2.tgz", + "integrity": "sha512-JZkJMZkAGFFPP2YqXZXPbMlMBgsxzE8ILs4lMIX/2o0L9UBw9O/Y3o6wFw/i9YLapcUJWwqbi3kdxIPdC62TIA==", + "dev": true, + "requires": { + "glob": "^7.1.3" + } + }, "safe-buffer": { "version": "5.2.1", "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.2.1.tgz", @@ -1510,6 +1640,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", @@ -1650,6 +1805,24 @@ } } }, + "tmp": { + "version": "0.2.1", + "resolved": "https://registry.npmjs.org/tmp/-/tmp-0.2.1.tgz", + "integrity": "sha512-76SUhtfqR2Ijn+xllcI5P1oyannHNHByD80W1q447gU3mp9G9PSpGdWmjUOHRDPiHYacIk66W7ubDTuPF3BEtQ==", + "dev": true, + "requires": { + "rimraf": "^3.0.0" + } + }, + "tmp-promise": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/tmp-promise/-/tmp-promise-3.0.2.tgz", + "integrity": "sha512-OyCLAKU1HzBjL6Ev3gxUeraJNlbNingmi8IrHHEsYH8LTmEuhvYfqvhn2F/je+mjf4N58UmZ96OMEy1JanSCpA==", + "dev": true, + "requires": { + "tmp": "^0.2.0" + } + }, "to-regex-range": { "version": "5.0.1", "resolved": "https://registry.npmjs.org/to-regex-range/-/to-regex-range-5.0.1.tgz", @@ -1700,6 +1873,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 ebd3890be2..a541b3eff8 100644 --- a/src/chains/filecoin/options/package.json +++ b/src/chains/filecoin/options/package.json @@ -53,12 +53,15 @@ "@ganache/options": "0.8.0", "@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", + "tmp-promise": "3.0.2", "ts-loader": "9.3.1", "ts-node": "10.9.1", "typescript": "4.7.4", @@ -66,6 +69,7 @@ "webpack-cli": "4.9.1" }, "dependencies": { + "@ganache/utils": "0.8.0", "keccak": "3.0.2" } } diff --git a/src/chains/filecoin/options/src/logging-options.ts b/src/chains/filecoin/options/src/logging-options.ts index e85ac3445c..5b67d58af5 100644 --- a/src/chains/filecoin/options/src/logging-options.ts +++ b/src/chains/filecoin/options/src/logging-options.ts @@ -1,5 +1,7 @@ -import { normalize } from "./helpers"; import { Definitions } from "@ganache/options"; +import { openSync, PathLike } from "fs"; +import { Logger, InternalLogger, createLogger } from "@ganache/utils"; +import { EOL } from "os"; export type LoggingConfig = { options: { @@ -18,22 +20,59 @@ export type LoggingConfig = { * ``` */ readonly logger: { - type: { - log(message?: any, ...optionalParams: any[]): void; - }; + rawType: Logger; + type: InternalLogger; hasDefault: true; }; + + /** + * The file to append logs to. + * + * Can be a filename, or an instance of URL. + * note: the URL scheme must be `file`, e.g., `file://path/to/file.log`. + * + * By default no log file is created. + */ + 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) { + const details = (err as Error).message; + 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.${EOL}${details}` + ); + } + return descriptor; + }, + + cliDescription: "The file to append logs to.", + 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..79488e39be --- /dev/null +++ b/src/chains/filecoin/options/tests/logging-options.test.ts @@ -0,0 +1,165 @@ +import assert from "assert"; +import { FilecoinOptionsConfig } from "../src"; +import sinon from "sinon"; +import { promises, closeSync } from "fs"; +const { unlink, open, readFile } = promises; +import tmp from "tmp-promise"; +import { resolve } from "path"; +import { URL } from "url"; +import { EOL } from "os"; + +describe("FilecoinOptionsConfig", () => { + describe("logging", () => { + describe("options", async () => { + function assertLogLine(logLine: string, message: string) { + const timestampPart = logLine.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 = logLine.substring(25); + + assert.strictEqual(messagePart, message, "Message does not match"); + } + + tmp.setGracefulCleanup(); + // we use tmp.dir() rather than tmp.file() here, because we don't want the file to exist + const tempFileDir = (await tmp.dir()).path; + const logfilePath = resolve(tempFileDir, "temp-file.log"); + + let spy: any; + + beforeEach(() => { + spy = sinon.spy(console, "log"); + }); + + afterEach(async () => { + spy.restore(); + + await unlink(logfilePath).catch(() => {}); + }); + + 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: logfilePath } + }); + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("resolves a file path as Buffer to descriptor", async () => { + const options = FilecoinOptionsConfig.normalize({ + logging: { file: Buffer.from(logfilePath, "utf8") } + }); + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("resolves a file URL as Buffer to descriptor", async () => { + const options = FilecoinOptionsConfig.normalize({ + logging: { file: new URL(`file://${logfilePath}`) } + }); + assert(typeof options.logging.file === "number"); + assert.doesNotThrow( + () => closeSync(options.logging.file), + "File descriptor not valid" + ); + }); + + it("fails if the process doesn't have write access to the file path provided", async () => { + await tmp.withFile(async ({ path }) => { + const handle = await open(path, "w"); + // set no permissions on the file + await handle.chmod(0); + await handle.close(); + + const errorMessage = `Failed to open log file ${path}. Please check if the file path is valid and if the process has write permissions to the directory.${EOL}`; // the specific error that follows this is OS dependent + + assert.throws( + () => + FilecoinOptionsConfig.normalize({ + logging: { file: path } + }), + (error: Error) => error.message.startsWith(errorMessage) + ); + }); + }); + + it("should append to the specified file", async () => { + const message = "message"; + const handle = await open(logfilePath, "w"); + await handle.write(`existing content${EOL}`); + await handle.close(); + + const options = FilecoinOptionsConfig.normalize({ + logging: { file: logfilePath } + }); + try { + options.logging.logger.log(message); + + const readHandle = await open(logfilePath, "r"); + const content = await readHandle.readFile({ encoding: "utf8" }); + await readHandle.close(); + + const lines = content.split(EOL); + + assert.strictEqual(lines.length, 3); // 2 lines + empty line at the end + assert.strictEqual(lines[0], "existing content"); + + assertLogLine(lines[1], message); + } finally { + await options.logging.logger.close(); + } + }); + + 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]); + } + }; + + const options = FilecoinOptionsConfig.normalize({ + logging: { + logger, + file: logfilePath + } + }); + + options.logging.logger.log("message", "param1", "param2"); + await options.logging.logger.close(); + assert.deepStrictEqual(calls, [["message", "param1", "param2"]]); + + const fromFile = await readFile(logfilePath, "utf8"); + assert(fromFile !== "", "Nothing written to the log file"); + + const lines = fromFile.split(EOL); + assert.strictEqual(lines.length, 2); // 1 line + empty line at the end + assertLogLine(lines[0], "message param1 param2"); + assert.strictEqual(lines[1], ""); + }); + }); + }); + }); +}); diff --git a/src/chains/filecoin/options/tsconfig.json b/src/chains/filecoin/options/tsconfig.json index 5dfe28e945..abb23aa723 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/core/tests/connector.test.ts b/src/packages/core/tests/connector.test.ts index 0969407b6a..1fe5963cc1 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.length = 0; + + 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 139d3feeba..6390513bec 100644 --- a/src/packages/ganache/npm-shrinkwrap.json +++ b/src/packages/ganache/npm-shrinkwrap.json @@ -1,6 +1,6 @@ { "name": "ganache", - "version": "7.7.6", + "version": "7.8.0", "lockfileVersion": 1, "requires": true, "dependencies": { diff --git a/src/packages/options/src/create.ts b/src/packages/options/src/create.ts index 491728c828..0c5d8d410d 100644 --- a/src/packages/options/src/create.ts +++ b/src/packages/options/src/create.ts @@ -48,7 +48,7 @@ function fill(options: any, target: any, def: any, namespace: any) { for (const [key, propDefinition] of entries) { let value = namespaceOptions[key]; if (value !== undefined) { - const normalized = propDefinition.normalize(value); + const normalized = propDefinition.normalize(value, config); if (normalized !== undefined) { checkForConflicts( key, @@ -63,7 +63,7 @@ function fill(options: any, target: any, def: 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, @@ -85,7 +85,7 @@ function fill(options: any, target: any, def: 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/package-lock.json b/src/packages/utils/package-lock.json index 8832d99df2..96dc74a8cf 100644 --- a/src/packages/utils/package-lock.json +++ b/src/packages/utils/package-lock.json @@ -787,6 +787,15 @@ "integrity": "sha1-jGStX9MNqxyXbiNE/+f3kqam30I=", "dev": true }, + "rimraf": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/rimraf/-/rimraf-3.0.2.tgz", + "integrity": "sha512-JZkJMZkAGFFPP2YqXZXPbMlMBgsxzE8ILs4lMIX/2o0L9UBw9O/Y3o6wFw/i9YLapcUJWwqbi3kdxIPdC62TIA==", + "dev": true, + "requires": { + "glob": "^7.1.3" + } + }, "safe-buffer": { "version": "5.2.1", "resolved": "https://registry.npmjs.org/safe-buffer/-/safe-buffer-5.2.1.tgz", @@ -889,6 +898,24 @@ "has-flag": "^4.0.0" } }, + "tmp": { + "version": "0.2.1", + "resolved": "https://registry.npmjs.org/tmp/-/tmp-0.2.1.tgz", + "integrity": "sha512-76SUhtfqR2Ijn+xllcI5P1oyannHNHByD80W1q447gU3mp9G9PSpGdWmjUOHRDPiHYacIk66W7ubDTuPF3BEtQ==", + "dev": true, + "requires": { + "rimraf": "^3.0.0" + } + }, + "tmp-promise": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/tmp-promise/-/tmp-promise-3.0.2.tgz", + "integrity": "sha512-OyCLAKU1HzBjL6Ev3gxUeraJNlbNingmi8IrHHEsYH8LTmEuhvYfqvhn2F/je+mjf4N58UmZ96OMEy1JanSCpA==", + "dev": true, + "requires": { + "tmp": "^0.2.0" + } + }, "to-regex-range": { "version": "5.0.1", "resolved": "https://registry.npmjs.org/to-regex-range/-/to-regex-range-5.0.1.tgz", diff --git a/src/packages/utils/package.json b/src/packages/utils/package.json index f7bda2b2ef..7b1b78cd24 100644 --- a/src/packages/utils/package.json +++ b/src/packages/utils/package.json @@ -59,6 +59,7 @@ "cross-env": "7.0.3", "mocha": "9.1.3", "sinon": "11.1.2", + "tmp-promise": "3.0.2", "ts-node": "10.9.1", "typescript": "4.7.4" }, diff --git a/src/packages/utils/src/things/logger.ts b/src/packages/utils/src/things/logger.ts new file mode 100644 index 0000000000..d66a8d6b6b --- /dev/null +++ b/src/packages/utils/src/things/logger.ts @@ -0,0 +1,68 @@ +import { createWriteStream } from "fs"; +import { format } from "util"; +import { EOL } from "os"; + +export type LogFunc = (message?: any, ...optionalParams: any[]) => void; + +export type Logger = { + log: LogFunc; +}; + +export type InternalLogger = Logger & { + close: () => Promise; +}; + +type LoggerConfig = { + baseLogger: Logger; + file?: number; +}; + +// this needs to match start of line with both CRLF and LF encoding (^ matches after _both_ CR and LF) +const START_OF_LINE = /^|(?<=\r?\n)/g; + +export function createLogger(config: LoggerConfig): InternalLogger { + const baseLog = (...params: any[]) => config.baseLogger.log(...params); + + if ("file" in config && config.file !== undefined) { + const fd = config.file; + + const diskLogFormatter = (message: string) => { + // trailing space after date is delimiter between date and message + const linePrefix = `${new Date().toISOString()} `; + return message.replace(START_OF_LINE, linePrefix); + }; + + const writeStream = createWriteStream(null, { fd }); + + const onError = err => + console.error(`Error writing to log file: ${err.message}`); + writeStream.on("error", onError); + + const log = (message: any, ...optionalParams: any[]) => { + // we are logging to a file, but we still need to write to console + baseLog(message, ...optionalParams); + + const formattedMessage: string = format(message, ...optionalParams); + writeStream.write(diskLogFormatter(formattedMessage) + EOL); + }; + + return { + log, + close: () => + new Promise((resolve, reject) => { + writeStream.close(err => { + if (err) { + reject(err); + } else { + resolve(); + } + }); + }) + }; + } else { + return { + log: baseLog, + close: async () => {} + }; + } +} diff --git a/src/packages/utils/tests/logger.test.ts b/src/packages/utils/tests/logger.test.ts new file mode 100644 index 0000000000..cb1cbbed00 --- /dev/null +++ b/src/packages/utils/tests/logger.test.ts @@ -0,0 +1,319 @@ +import assert from "assert"; +import sinon from "sinon"; +import { createLogger } from "../src/things/logger"; +import { openSync, promises, closeSync, writeSync } from "fs"; +const { unlink, readFile } = promises; +import { EOL } from "os"; +import tmp from "tmp-promise"; +import { resolve } from "path"; + +describe("createLogger()", async () => { + tmp.setGracefulCleanup(); + // we use tmp.dir() rather than tmp.file() here, because we don't want the file to exist + const tempFileDir = (await tmp.dir()).path; + const logfilePath = resolve(tempFileDir, "log-file.log"); + + const getFixtureDescriptor = () => openSync(logfilePath, "a"); + + afterEach(async () => { + await unlink(logfilePath).catch(() => {}); + }); + + const createBaseLogger = () => { + const calls: any[][] = []; + return { + baseLogger: { + log: (message, ...params) => { + calls.push([message, ...params]); + } + }, + calls + }; + }; + + describe("baseLogger", () => { + it("binds the log function to the baseLogger", () => { + const baseLogger = { + log: function () { + assert.strictEqual( + this, + baseLogger, + "`this` does not reference the baseLogger" + ); + } + }; + + const logger = createLogger({ baseLogger }); + + logger.log("test message"); + }); + + it("binds the log function to the baseLogger, when a file is specified", async () => { + const baseLogger = { + log: function () { + assert.strictEqual( + this, + baseLogger, + "`this` does not reference the baseLogger" + ); + } + }; + + const file = getFixtureDescriptor(); + try { + const logger = createLogger({ baseLogger, file }); + + logger.log("test message"); + await logger.close(); + } catch { + // logger.close() will close the underlying descriptor, so this only needs to + // happen if it fails + closeSync(file); + } + }); + + it("uses the reassigned log function", () => { + const baseLogger = { + log: (message: any, ...optionalArgs: any[]) => {} + }; + + const logger = createLogger({ baseLogger }); + + baseLogger.log = (message: any, ...optionalArgs: any[]) => { + assert.strictEqual(message, "test message"); + assert.deepStrictEqual(optionalArgs, ["param1", "param2"]); + }; + + logger.log("test message", "param1", "param2"); + }); + }); + + describe("log()", () => { + const splitLogLine = (logLine: string) => { + // The log line is in the format: + // ` ` + // where the timestamp is 24 characters long + // the delimiting space is at index 24 + // and the message starts at index 25 + const timestampPart = logLine.slice(0, 24); + const delimiter = logLine[24]; + const messagePart = logLine.slice(25); + + return { + timestampPart, + delimiter, + messagePart + }; + }; + + const timestampRegex = /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z$/; + + const message = "test message"; + + it("creates a baseLogger() logger", () => { + const { baseLogger, calls } = createBaseLogger(); + const { log } = createLogger({ baseLogger }); + + log(message); + + assert.deepStrictEqual( + calls.length, + 1, + "baseLogger() was called unexpected number of times." + ); + + assert.deepStrictEqual(calls, [[message]]); + }); + + it("still calls baseLogger() when a file is specified", async () => { + const file = getFixtureDescriptor(); + + const { baseLogger, calls } = createBaseLogger(); + + const { log, close } = createLogger({ + file, + baseLogger + }); + + try { + log(message); + await close(); + } catch (err) { + // logger.close() will close the underlying descriptor, so this only needs to + // happen if it fails + closeSync(file); + throw err; + } + + assert.strictEqual( + calls.length, + 1, + "baseLogger() was called unexpected number of times." + ); + + assert.deepStrictEqual(calls, [[message]]); + }); + + it("writes to the file provided", async () => { + const file = getFixtureDescriptor(); + + const { baseLogger } = createBaseLogger(); + + const { log, close } = createLogger({ + file, + baseLogger + }); + + try { + log(`${message} 0`); + log(`${message} 1`); + log(`${message} 2`); + await close(); + } catch (err) { + // logger.close() will close the underlying descriptor, so only need to + // explicitly close the descriptor if it fails to close + closeSync(file); + throw err; + } + + const fileContents = await readFile(logfilePath, "utf8"); + const logLines = fileContents.split(EOL); + + // 4, because there's a \n at the end of each line, creating an empty entry + assert.strictEqual(logLines.length, 4); + assert.strictEqual(logLines[3], ""); + + logLines.slice(0, 3).forEach((logLine, lineNumber) => { + const { timestampPart, delimiter, messagePart } = splitLogLine(logLine); + + assert(timestampRegex.test(timestampPart), "Unexpected timestamp."); + assert.strictEqual(delimiter, " ", "Unexpected delimiter."); + assert.strictEqual( + messagePart, + `${message} ${lineNumber}`, + "Unexpected message." + ); + }); + }); + + const endsOfLine = [ + { eol: "\r\n", identifier: "CRLF" }, + { eol: "\n", name: "LF" } + ]; + + endsOfLine.forEach(({ eol, identifier }) => { + it(`timestamps each line on multi-line log messages split by ${identifier}`, async () => { + const file = getFixtureDescriptor(); + + const { baseLogger } = createBaseLogger(); + + const { log, close } = createLogger({ + file, + baseLogger + }); + + const expectedLines = ["multi", "line", "message"]; + + let loggedLines: string[]; + try { + log(expectedLines.join(eol)); + await close(); + } catch (err) { + // logger.close() will close the underlying descriptor, so only need to + // explicitly close the descriptor if it fails to close + closeSync(file); + throw err; + } + + const fileContents = await readFile(logfilePath, "utf8"); + loggedLines = fileContents.split(/\n|\r\n/); + // 4, because there's a \n at the end of each line, creating an empty entry + assert.strictEqual( + loggedLines.length, + 4, + "Unexpected number of lines in the log file" + ); + assert.strictEqual(loggedLines[3], ""); + + loggedLines.slice(0, 3).forEach((logLine, lineNumber) => { + const { timestampPart, delimiter, messagePart } = + splitLogLine(logLine); + + assert(timestampRegex.test(timestampPart), "Unexpected timestamp"); + assert.strictEqual(delimiter, " ", "Unexpected delimiter"); + assert.strictEqual(messagePart, expectedLines[lineNumber]); + }); + }); + }); + + it("writes to stderr if the file descriptor is invalid", async () => { + // unlikely that this will be a valid file descriptor + const fd = 1234567890; + const { baseLogger } = createBaseLogger(); + const spy = sinon.spy(console, "error"); + + const { log, close } = createLogger({ + file: fd, + baseLogger + }); + + log("Invalid descriptor"); + + await close(); + + assert.strictEqual( + spy.withArgs( + "Error writing to log file: EBADF: bad file descriptor, close" + ).callCount, + 1 + ); + spy.restore(); + }); + + it("continues to log to baseLogger after file descriptor is closed", async () => { + const { baseLogger, calls } = createBaseLogger(); + const file = getFixtureDescriptor(); + + const { log, close } = createLogger({ + file, + baseLogger + }); + + closeSync(file); + + log("Oh noes!"); + log("The descriptor is cloes[d]!"); + + await close(); + + assert.deepStrictEqual(calls, [ + ["Oh noes!"], + ["The descriptor is cloes[d]!"] + ]); + }); + }); + + describe("close()", () => { + it("closes the underlying descriptor", async () => { + const file = getFixtureDescriptor(); + const { baseLogger } = createBaseLogger(); + const { close } = createLogger({ + file, + baseLogger + }); + + try { + await close(); + } catch (err) { + // logger.close() will close the underlying descriptor, so only need to + // explicitly close the descriptor if it fails to close + closeSync(file); + throw err; + } + + assert.throws(() => writeSync(file, "Descriptor is closed"), { + code: "EBADF" + }); + }); + }); +});