From b53b33e3b6942ba18c366c6c2676f8caf83fa95c Mon Sep 17 00:00:00 2001 From: Koen Vlaswinkel Date: Tue, 26 Mar 2024 15:58:39 +0100 Subject: [PATCH 1/3] Use file handle in TeeLogger This switches the `TeeLogger` from using the `appendFile` function to manually opening and closing a file handle and calling `appendFile` on the file handle. This results in a more efficient implementation as the file handle is only opened once and closed once, instead of being opened and closed for every log message. This should result in less "too many open files" errors. --- .../ql-vscode/src/common/disposable-object.ts | 4 +++ .../src/common/logging/tee-logger.ts | 24 ++++++++++--- .../contextual/query-resolver.ts | 15 ++++---- .../src/local-queries/local-query-run.ts | 13 +++++++ .../ql-vscode/src/local-queries/run-query.ts | 34 +++++++++++-------- .../logging/output-channel-logger.test.ts | 8 ++++- 6 files changed, 71 insertions(+), 27 deletions(-) diff --git a/extensions/ql-vscode/src/common/disposable-object.ts b/extensions/ql-vscode/src/common/disposable-object.ts index 8c4cfd4950f..4b8e20180b3 100644 --- a/extensions/ql-vscode/src/common/disposable-object.ts +++ b/extensions/ql-vscode/src/common/disposable-object.ts @@ -88,3 +88,7 @@ export class DisposableObject implements Disposable { } } } + +export function isDisposable(obj: unknown): obj is Disposable { + return obj !== undefined && typeof (obj as Disposable).dispose === "function"; +} diff --git a/extensions/ql-vscode/src/common/logging/tee-logger.ts b/extensions/ql-vscode/src/common/logging/tee-logger.ts index 64bb5d4e0fe..24defa7484a 100644 --- a/extensions/ql-vscode/src/common/logging/tee-logger.ts +++ b/extensions/ql-vscode/src/common/logging/tee-logger.ts @@ -1,7 +1,10 @@ -import { appendFile, ensureFile } from "fs-extra"; +import { ensureFile } from "fs-extra"; +import { open } from "node:fs/promises"; +import type { FileHandle } from "node:fs/promises"; import { isAbsolute } from "path"; import { getErrorMessage } from "../helpers-pure"; import type { Logger, LogOptions } from "./logger"; +import type { Disposable } from "../disposable-object"; /** * An implementation of {@link Logger} that sends the output both to another {@link Logger} @@ -10,9 +13,10 @@ import type { Logger, LogOptions } from "./logger"; * The first time a message is written, an additional banner is written to the underlying logger * pointing the user to the "side log" file. */ -export class TeeLogger implements Logger { +export class TeeLogger implements Logger, Disposable { private emittedRedirectMessage = false; private error = false; + private fileHandle: FileHandle | undefined = undefined; public constructor( private readonly logger: Logger, @@ -37,11 +41,15 @@ export class TeeLogger implements Logger { if (!this.error) { try { + if (!this.fileHandle) { + await ensureFile(this.location); + + this.fileHandle = await open(this.location, "a"); + } + const trailingNewline = options.trailingNewline ?? true; - await ensureFile(this.location); - await appendFile( - this.location, + await this.fileHandle.appendFile( message + (trailingNewline ? "\n" : ""), { encoding: "utf8", @@ -50,6 +58,7 @@ export class TeeLogger implements Logger { } catch (e) { // Write an error message to the primary log, and stop trying to write to the side log. this.error = true; + this.fileHandle = undefined; const errorMessage = getErrorMessage(e); await this.logger.log( `Error writing to additional log file: ${errorMessage}`, @@ -65,4 +74,9 @@ export class TeeLogger implements Logger { show(preserveFocus?: boolean): void { this.logger.show(preserveFocus); } + + dispose(): void { + void this.fileHandle?.close(); + this.fileHandle = undefined; + } } diff --git a/extensions/ql-vscode/src/language-support/contextual/query-resolver.ts b/extensions/ql-vscode/src/language-support/contextual/query-resolver.ts index 4ff744f3c89..4302b18fa92 100644 --- a/extensions/ql-vscode/src/language-support/contextual/query-resolver.ts +++ b/extensions/ql-vscode/src/language-support/contextual/query-resolver.ts @@ -92,11 +92,12 @@ export async function runContextualQuery( void extLogger.log( `Running contextual query ${query}; results will be stored in ${queryRun.outputDir.querySaveDir}`, ); - const results = await queryRun.evaluate( - progress, - token, - new TeeLogger(qs.logger, queryRun.outputDir.logPath), - ); - await cleanup?.(); - return results; + const teeLogger = new TeeLogger(qs.logger, queryRun.outputDir.logPath); + + try { + return await queryRun.evaluate(progress, token, teeLogger); + } finally { + await cleanup?.(); + teeLogger.dispose(); + } } diff --git a/extensions/ql-vscode/src/local-queries/local-query-run.ts b/extensions/ql-vscode/src/local-queries/local-query-run.ts index bb5b9ee1e7e..43615395392 100644 --- a/extensions/ql-vscode/src/local-queries/local-query-run.ts +++ b/extensions/ql-vscode/src/local-queries/local-query-run.ts @@ -25,6 +25,7 @@ import { redactableError } from "../common/errors"; import type { LocalQueries } from "./local-queries"; import { tryGetQueryMetadata } from "../codeql-cli/query-metadata"; import { telemetryListener } from "../common/vscode/telemetry"; +import { isDisposable } from "../common/disposable-object"; function formatResultMessage(result: CoreQueryResults): string { switch (result.resultType) { @@ -61,6 +62,10 @@ export class LocalQueryRun { private readonly localQueries: LocalQueries, private readonly queryInfo: LocalQueryInfo, private readonly dbItem: DatabaseItem, + /** + * The logger is only available while the query is running and will be disposed of when the + * query completes. + */ public readonly logger: Logger, // Public so that other clients, like the debug adapter, know where to send log output private readonly queryHistoryManager: QueryHistoryManager, private readonly cliServer: CodeQLCliServer, @@ -92,6 +97,10 @@ export class LocalQueryRun { // Note we must update the query history view after showing results as the // display and sorting might depend on the number of results await this.queryHistoryManager.refreshTreeView(); + + if (isDisposable(this.logger)) { + this.logger.dispose(); + } } /** @@ -110,6 +119,10 @@ export class LocalQueryRun { err.message = `Error running query: ${err.message}`; this.queryInfo.failureReason = err.message; await this.queryHistoryManager.refreshTreeView(); + + if (isDisposable(this.logger)) { + this.logger.dispose(); + } } /** diff --git a/extensions/ql-vscode/src/local-queries/run-query.ts b/extensions/ql-vscode/src/local-queries/run-query.ts index 0d5299ed27d..1f06c656b56 100644 --- a/extensions/ql-vscode/src/local-queries/run-query.ts +++ b/extensions/ql-vscode/src/local-queries/run-query.ts @@ -47,21 +47,27 @@ export async function runQuery({ undefined, ); - const completedQuery = await queryRun.evaluate( - progress, - token, - new TeeLogger(queryRunner.logger, queryRun.outputDir.logPath), + const teeLogger = new TeeLogger( + queryRunner.logger, + queryRun.outputDir.logPath, ); - if (completedQuery.resultType !== QueryResultType.SUCCESS) { - void showAndLogExceptionWithTelemetry( - extLogger, - telemetryListener, - redactableError`Failed to run ${basename(queryPath)} query: ${ - completedQuery.message ?? "No message" - }`, - ); - return; + try { + const completedQuery = await queryRun.evaluate(progress, token, teeLogger); + + if (completedQuery.resultType !== QueryResultType.SUCCESS) { + void showAndLogExceptionWithTelemetry( + extLogger, + telemetryListener, + redactableError`Failed to run ${basename(queryPath)} query: ${ + completedQuery.message ?? "No message" + }`, + ); + return; + } + + return completedQuery; + } finally { + teeLogger.dispose(); } - return completedQuery; } diff --git a/extensions/ql-vscode/test/common/logging/output-channel-logger.test.ts b/extensions/ql-vscode/test/common/logging/output-channel-logger.test.ts index 33796083299..0df03c32ea3 100644 --- a/extensions/ql-vscode/test/common/logging/output-channel-logger.test.ts +++ b/extensions/ql-vscode/test/common/logging/output-channel-logger.test.ts @@ -5,6 +5,7 @@ import { dirSync } from "tmp"; import type { BaseLogger, Logger } from "../../../src/common/logging"; import { TeeLogger } from "../../../src/common/logging"; import { OutputChannelLogger } from "../../../src/common/logging/vscode"; +import type { Disposable } from "../../../src/common/disposable-object"; jest.setTimeout(999999); @@ -66,6 +67,8 @@ describe("OutputChannelLogger tests", function () { // should have created 1 side log expect(readdirSync(tempFolders.storagePath.name)).toEqual(["hucairz"]); + + hucairz.dispose(); }); it("should create a side log", async () => { @@ -86,12 +89,15 @@ describe("OutputChannelLogger tests", function () { expect( readFileSync(join(tempFolders.storagePath.name, "second"), "utf8"), ).toBe("yyy\n"); + + first.dispose(); + second.dispose(); }); function createSideLogger( logger: Logger, additionalLogLocation: string, - ): BaseLogger { + ): BaseLogger & Disposable { return new TeeLogger( logger, join(tempFolders.storagePath.name, additionalLogLocation), From 139c4555d9919ff74965b40eb057afd23bfd603a Mon Sep 17 00:00:00 2001 From: Koen Vlaswinkel Date: Wed, 27 Mar 2024 10:43:31 +0100 Subject: [PATCH 2/3] Use Disposable type instead of isDisposable function --- extensions/ql-vscode/src/common/disposable-object.ts | 4 ---- .../ql-vscode/src/local-queries/local-query-run.ts | 12 ++++-------- 2 files changed, 4 insertions(+), 12 deletions(-) diff --git a/extensions/ql-vscode/src/common/disposable-object.ts b/extensions/ql-vscode/src/common/disposable-object.ts index 4b8e20180b3..8c4cfd4950f 100644 --- a/extensions/ql-vscode/src/common/disposable-object.ts +++ b/extensions/ql-vscode/src/common/disposable-object.ts @@ -88,7 +88,3 @@ export class DisposableObject implements Disposable { } } } - -export function isDisposable(obj: unknown): obj is Disposable { - return obj !== undefined && typeof (obj as Disposable).dispose === "function"; -} diff --git a/extensions/ql-vscode/src/local-queries/local-query-run.ts b/extensions/ql-vscode/src/local-queries/local-query-run.ts index 43615395392..3f43f119552 100644 --- a/extensions/ql-vscode/src/local-queries/local-query-run.ts +++ b/extensions/ql-vscode/src/local-queries/local-query-run.ts @@ -25,7 +25,7 @@ import { redactableError } from "../common/errors"; import type { LocalQueries } from "./local-queries"; import { tryGetQueryMetadata } from "../codeql-cli/query-metadata"; import { telemetryListener } from "../common/vscode/telemetry"; -import { isDisposable } from "../common/disposable-object"; +import type { Disposable } from "../common/disposable-object"; function formatResultMessage(result: CoreQueryResults): string { switch (result.resultType) { @@ -66,7 +66,7 @@ export class LocalQueryRun { * The logger is only available while the query is running and will be disposed of when the * query completes. */ - public readonly logger: Logger, // Public so that other clients, like the debug adapter, know where to send log output + public readonly logger: Logger & Disposable, // Public so that other clients, like the debug adapter, know where to send log output private readonly queryHistoryManager: QueryHistoryManager, private readonly cliServer: CodeQLCliServer, ) {} @@ -98,9 +98,7 @@ export class LocalQueryRun { // display and sorting might depend on the number of results await this.queryHistoryManager.refreshTreeView(); - if (isDisposable(this.logger)) { - this.logger.dispose(); - } + this.logger.dispose(); } /** @@ -120,9 +118,7 @@ export class LocalQueryRun { this.queryInfo.failureReason = err.message; await this.queryHistoryManager.refreshTreeView(); - if (isDisposable(this.logger)) { - this.logger.dispose(); - } + this.logger.dispose(); } /** From e52a08db4d11a5a1a17aa4a132b314665ae5866e Mon Sep 17 00:00:00 2001 From: Koen Vlaswinkel Date: Wed, 27 Mar 2024 10:46:56 +0100 Subject: [PATCH 3/3] Safely close file handle in all cases --- .../ql-vscode/src/common/logging/tee-logger.ts | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/extensions/ql-vscode/src/common/logging/tee-logger.ts b/extensions/ql-vscode/src/common/logging/tee-logger.ts index 24defa7484a..991bcdd422c 100644 --- a/extensions/ql-vscode/src/common/logging/tee-logger.ts +++ b/extensions/ql-vscode/src/common/logging/tee-logger.ts @@ -58,6 +58,13 @@ export class TeeLogger implements Logger, Disposable { } catch (e) { // Write an error message to the primary log, and stop trying to write to the side log. this.error = true; + try { + await this.fileHandle?.close(); + } catch (e) { + void this.logger.log( + `Failed to close file handle: ${getErrorMessage(e)}`, + ); + } this.fileHandle = undefined; const errorMessage = getErrorMessage(e); await this.logger.log( @@ -76,7 +83,13 @@ export class TeeLogger implements Logger, Disposable { } dispose(): void { - void this.fileHandle?.close(); + try { + void this.fileHandle?.close(); + } catch (e) { + void this.logger.log( + `Failed to close file handle: ${getErrorMessage(e)}`, + ); + } this.fileHandle = undefined; } }